keycloak-pattern/docs/experiment-a6-latency-injection.md

A-6 — 끊기지 않고 느려지기만 하면 어떻게 되는가

브랜치 feature/keycloak-a6-latency-injection · 증거 docs/evidence/a6-latency-injection/ · 2026-09-04 13:10–13:35 KST

실제 장애의 대부분은 완전 사망이 아니라 느려짐이다. 그리고 느려짐은 사망보다 진단하기 어렵다 — 헬스체크가 통과하기 때문이다.

---

0. 결론부터

측정	값
주입한 네트워크 지연	200 ms
로그인 응답 시간	66 ms → 1,872 ms (28배)
동시 20건에서 최대 응답	22.2 초
커넥션 획득 대기 최대	20,000 ms
readiness 프로브	타임아웃으로 실패

200밀리초가 22초가 됐다. 지연은 왕복 횟수만큼 곱해지고, 커넥션 풀에서 한 번 더 곱해진다.

---

1. 설계 — 한 실험에서 A/B 가 되는 배치

   kc-lab-2                        kc-lab-1
   ┌──────────────────┐            ┌──────────────────┐
   │ postgres         │            │ keycloak-1       │
   │ keycloak-0       │            │                  │
   │   └─ cni0 로 직행 │◀─ VXLAN ──▶│   └─ 오버레이 경유 │
   └──────────────────┘            └──────────────────┘
        지연 없음                        여기만 느려진다

postgres 가 보내는 패킷만 지연시키면 keycloak-1 의 DB 접근만 느려지고 keycloak-0 은 그대로다. 대조군이 같은 실험 안에 있다.

기준선은 거의 같았다.

  keycloak-0  평균 70 ms
  keycloak-1  평균 66 ms

---

2. 주입을 두 번 실패했다

실패 ① — eth0 이라는 인터페이스가 없다

ssh kc-lab-2 'sudo tc qdisc add dev eth0 root handle 1: prio'

Cannot find device "eth0"

Debian 클라우드 이미지는 예측 가능한 인터페이스 이름을 쓴다.

enp1s0    UP    52:54:00:aa:bb:12

en (ethernet) + p1 (PCI bus 1) + s0 (slot 0). 이름이 하드웨어 위치에서 나오므로 NIC 순서가 바뀌어도 이름이 안 바뀐다.

실패 ② — enp1s0 에서는 파드 IP 가 보이지 않는다

여기가 핵심이다. 노드 간 파드 통신은 flannel VXLAN 으로 캡슐화된다.

   원래 패킷:   src=10.42.1.76(postgres)  dst=10.42.0.42(keycloak-1)
        │
        ▼  flannel.1 에서 캡슐화
   실제 패킷:   src=192.168.122.12(노드)   dst=192.168.122.11(노드)  UDP 8472
                └─ 안쪽에 원래 패킷이 통째로 들어 있다
        │
        ▼
   enp1s0 로 나간다

enp1s0 에서 match ip src 10.42.1.76 은 절대 일치하지 않는다. 그 IP 는 페이로드 안에 있고, 헤더에는 노드 IP 만 있다.

성공 — flannel.1 에 건다

ssh kc-lab-2 '
  sudo tc qdisc add dev flannel.1 root handle 1: prio
  sudo tc qdisc add dev flannel.1 parent 1:3 handle 30: netem delay 200ms
  sudo tc filter add dev flannel.1 protocol ip parent 1:0 prio 3 \
       u32 match ip src 10.42.1.76/32 flowid 1:3'

flannel.1 은 캡슐화 직전 단계이므로 여기서는 파드 IP 가 보인다.

검증 — 카운터로 확인한다

qdisc netem 30: parent 1:3 limit 1000 delay 200ms
 Sent 18388 bytes 150 pkt (dropped 0, overlimits 0 requeues 0)
                  ───────
                  실제로 지연 밴드를 통과했다

A-1·A-5 와 같은 교훈이 세 번째로 나왔다. 주입을 넣은 것과 걸린 것은 다르다. 카운터를 봐야 한다.

개념 — tc 의 계층 구조

   qdisc (큐 규율)     인터페이스에 붙는 패킷 스케줄러
     ├─ prio           우선순위 밴드 3개로 나눈다
     │    ├─ 1:1 (기본)
     │    ├─ 1:2 (기본)
     │    └─ 1:3  ← 여기에 netem 을 붙인다
     └─ filter         어떤 패킷을 어느 밴드로 보낼지

netem 을 root 에 바로 붙이면 모든 트래픽이 느려진다. prio + filter 를 쓰면 고른 트래픽만 느려진다.

---

3. 결과 — 지연은 곱해진다

=== 두 노드 지연 비교 (기준선: k0=70ms k1=66ms) ===
  keycloak-0  평균   41 ms   최대   57 ms      ← 영향 없음
  keycloak-1  평균 1872 ms   최대 1887 ms      ← 28배

왜 200ms 가 1,872ms 가 되는가

A-0 에서 잡은 로그인 트랜잭션의 SQL 이 답이다.

BEGIN
select ... from OFFLINE_USER_SESSION ...
select VERSION ... for no key update skip locked
select ... from OFFLINE_CLIENT_SESSION ...
select VERSION ... for no key update skip locked
insert into OFFLINE_USER_SESSION ...
insert into OFFLINE_CLIENT_SESSION ...
SET LOCAL synchronous_commit TO OFF
COMMIT

왕복이 아홉 번이다.

   200 ms × 9 왕복 ≈ 1,800 ms      실측 1,872 ms

네트워크 지연은 왕복 횟수만큼 증폭된다. "DB 가 200ms 느려졌다"는 "애플리케이션이 200ms 느려졌다"가 아니다. 쿼리 수를 줄이는 것이 지연 환경에서 결정적인 이유가 이것이다.

---

4. 동시 부하 — 여기서 진짜 고장이 난다

동시 20건을 keycloak-1 에 보냈다.

  200  1.911    200  1.913    200  1.958    200  1.981
  200  3.441    200  4.841    200  6.257    200  7.704
  200  9.104    200 10.539    200 11.951    200 13.351
  200 14.785    200 16.189    200 17.625    200 19.053
  200 20.495    200 21.905    200 22.228    200 22.230

전부 성공(200)했지만 응답 시간이 1.9초에서 22.2초까지 계단으로 늘어난다.

   1.9 → 3.4 → 4.8 → 6.2 → 7.7 → 9.1 → 10.5 → ...
        ────  ────  ────  ────
        약 1.4초 간격 — 앞 요청이 커넥션을 놓아줄 때까지 줄을 선다

전형적인 큐잉이다. 커넥션 수는 유한하고, 각 요청이 커넥션을 1.9초씩 붙잡고 있으므로 뒤에 온 요청은 그만큼 기다린다.

커넥션 풀 지표가 증언한다

  agroal_blocking_time_max_milliseconds   20000.0    ← 20초를 기다린 요청이 있다
  agroal_blocking_time_average_milliseconds  281.0
  agroal_max_used_count                      19.0    ← 풀이 19개까지 늘었다
  agroal_acquire_count_total                672.0
  agroal_active_count                         0.0    ← 부하가 끝나 지금은 0

그리고 헬스체크가 무너진다

Warning  Unhealthy  pod/keycloak-1  Readiness probe failed:
  Get "http://10.42.0.42:9000/health/ready": context deadline exceeded

readiness 프로브 자체가 타임아웃됐다.

연쇄 고장의 모양

   DB 가 느려진다
        ↓
   요청이 커넥션을 오래 붙잡는다
        ↓
   커넥션 풀이 고갈된다
        ↓
   새 요청이 줄을 선다 (최대 20초)
        ↓
   헬스체크도 줄에 선다 → 타임아웃 → NotReady
        ↓
   그 노드가 로드밸런서에서 빠진다
        ↓
   ★ 남은 노드로 트래픽이 몰린다 → 그 노드도 같은 길을 간다

마지막 화살표가 무서운 부분이다. 느려짐은 전파된다. A-2(DB 완전 정지)는 즉시 503 으로 드러나 오히려 명확했지만, 느려짐은 살아 있는 노드를 하나씩 무너뜨린다.

---

5. 빗나간 예측 — 낙관적 락 충돌은 늘지 않았다

계획서에 이렇게 적었다.

낙관적 락 충돌 증가 — 트랜잭션이 길어져 VERSION 충돌이 늘어야 한다

  관련 로그 줄수: 0

하나도 없었다. 이유가 명확하다.

   로그인   →  매번 새 세션 행을 INSERT      →  다툴 상대가 없다
   refresh  →  같은 세션 행을 UPDATE         →  여기서 다툰다

충돌은 같은 행을 동시에 고칠 때만 일어난다. 로그인 부하로는 재현되지 않는다. 이건 B-3(refresh 토큰 경쟁)의 영역이며, 거기서 지연을 함께 주면 충돌률이 올라갈 것이다.

예측을 적어두지 않았다면 "충돌이 없네" 하고 넘어갔을 것이다. 빗나간 예측이 다음 실험의 설계를 정해준다.

---

6. 복구

ssh kc-lab-2 'sudo tc qdisc del dev flannel.1 root'

  keycloak-0  평균 43 ms
  keycloak-1  평균 51 ms      ← 즉시 정상

파드 재시작 없이 즉시 회복. 커넥션 풀도 스스로 정상화됐다.

---

7. 운영에 주는 것

알게 된 것	함의
지연은 왕복 횟수만큼 곱해진다	DB 지연 대책은 "쿼리 수 줄이기"가 먼저다
커넥션 풀에서 한 번 더 곱해진다	풀 크기와 타임아웃이 장애 반경을 정한다
헬스체크도 줄에 선다	프로브 타임아웃이 풀 대기보다 짧아야 격리가 제때 된다
느려짐은 전파된다	노드를 빼면 남은 노드가 더 빨리 무너진다
up 도 readiness 도 늦게 반응	응답 시간 분포(p95/p99)를 봐야 한다

이 실험대에 없는 알림

지금 관측 스택에는 지연 분포 지표가 없다. agroal_blocking_time_* 은 있지만 히스토그램이 아니라 평균/최대뿐이다.

# 있으면 좋았을 것
histogram_quantile(0.99, rate(http_server_requests_seconds_bucket[5m]))

A-2 에서 kube-state-metrics 가 빠진 것을 찾았고, 여기서는 응답 시간 히스토그램이 빠진 것을 찾았다. 둘 다 보완 항목이다.

---

8. 재현 절차 (명령어)

# 1. 인터페이스 이름 확인 — eth0 이 아니다
ssh kc-lab-2 'ip -brief link show | grep -E "flannel|cni|enp"'

# 2. 오버레이 인터페이스에 건다 (enp1s0 에서는 파드 IP 가 안 보인다)
ssh kc-lab-2 '
  sudo tc qdisc add dev flannel.1 root handle 1: prio
  sudo tc qdisc add dev flannel.1 parent 1:3 handle 30: netem delay 200ms
  sudo tc filter add dev flannel.1 protocol ip parent 1:0 prio 3 \
       u32 match ip src <postgres 파드IP>/32 flowid 1:3'

# 3. 걸렸는지 카운터로 확인 — Sent 가 0 이면 해석 금지
ssh kc-lab-2 'sudo tc -s qdisc show dev flannel.1 | grep -A2 netem'

# 4. 단일 요청 지연 (대조군은 같은 노드의 keycloak-0)
kubectl -n keycloak-lab run t --rm -i --restart=Never --image=curlimages/curl:8.11.1 \
  --command -- curl -s -o /dev/null -w '%{time_total}\n' -X POST http://<pod>:8080/realms/master/protocol/openid-connect/token ...

# 5. 동시 부하로 풀 고갈 재현
#    ( curl ... ) & 를 20개 띄우고 wait

# 6. 풀 지표
curl -s http://<pod>:9000/metrics | grep -E '^agroal_(blocking_time|max_used|awaiting)'

# 7. 해제
ssh kc-lab-2 'sudo tc qdisc del dev flannel.1 root'

---

9. 다음 실험에 남기는 것

실험	이 실험이 준 것
B-3 refresh 경쟁	지연을 함께 주면 낙관적 락 충돌이 재현될 것 — 여기서는 안 됐다
B-1 저장소 지연 (Q3 제약)	같은 기법을 Redis 앞에 쓴다
관측 보완	응답 시간 히스토그램이 없다
구성	프로브 타임아웃 < 커넥션 풀 대기여야 격리가 제때 된다