docs: A-6 — 200ms of network delay becomes 22 seconds of user latency

Nine database round trips per login multiply the injected delay to 1.9 seconds, and connection pool queueing multiplies it again under twenty concurrent requests. The readiness probe joins the same queue and times out, so the node leaves the load balancer and pushes its load onto the one still standing. Two injections missed first: the guest interface is enp1s0 rather than eth0, and a filter on it can never match a pod IP because flannel has already encapsulated the packet. The delay has to go on flannel.1, before encapsulation. The predicted rise in optimistic lock conflicts did not happen, because logins insert new rows rather than contending for one. That belongs to B-3. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-09-04 13:18:10 +09:00
parent 2fa77a899e
commit dba0c3975c
11 changed files with 657 additions and 0 deletions
@@ -0,0 +1,22 @@
+=== 배치 — 왜 A/B 가 되는가 ===
+  postgres  10.42.1.76  (kc-lab-2)
+  keycloak-0 10.42.1.77 (kc-lab-2) → DB 와 같은 노드, cni0 로 직행
+  keycloak-1 10.42.0.42 (kc-lab-1) → DB 와 다른 노드, VXLAN 을 건넌다  ← 여기에 지연을 건다
+
+=== 사용 가능한 커넥션 풀 지표 ===
+agroal_acquire_count_total
+agroal_active_count
+agroal_available_count
+agroal_awaiting_count
+agroal_blocking_time_average_milliseconds
+agroal_blocking_time_max_milliseconds
+agroal_blocking_time_total_milliseconds
+agroal_creation_count_total
+agroal_creation_time_average_milliseconds
+agroal_creation_time_max_milliseconds
+agroal_creation_time_total_milliseconds
+agroal_destroy_count_total
+
+=== 기준선 지연 — 각 노드에서 로그인 20회 ===
+  keycloak-0  평균 70 ms
+  keycloak-1  평균 66 ms
@@ -0,0 +1,25 @@
+=== 주입: postgres(10.42.1.76) 가 보내는 패킷만 200ms 지연 (kc-lab-2 eth0) ===
+  prio qdisc 로 밴드를 나누고, u32 필터로 출발지 IP 가 postgres 인 것만 3번 밴드로 보낸다
+Cannot find device "eth0"
+Cannot find device "eth0"
+적용완료
+Cannot find device "eth0"
+Cannot find device "eth0"
+  주입: 13:14:55
+
+=== [검증] 지연이 실제로 걸렸는가 — 두 노드 비교 ===
+  keycloak-0  평균 43 ms   최대 64 ms
+  keycloak-1  평균 47 ms   최대 70 ms
+
+=== 커넥션 풀 상태 ===
+--- keycloak-0 ---
+  agroal_blocking_time_max_milliseconds 102.0
+  agroal_active_count 0.0
+  agroal_awaiting_count 0.0
+  agroal_blocking_time_average_milliseconds 0.0
+  agroal_available_count 2.0
+  agroal_blocking_time_max_milliseconds 164.0
+  agroal_active_count 0.0
+  agroal_awaiting_count 0.0
+  agroal_blocking_time_average_milliseconds 0.0
+  agroal_available_count 2.0
@@ -0,0 +1,20 @@
+=== 오버레이 인터페이스 확인 ===
+flannel.1        UNKNOWN        a6:b2:62:04:c1:a4 <BROADCAST,MULTICAST,UP,LOWER_UP> 
+cni0             UP             5a:77:1a:e2:b0:a4 <BROADCAST,MULTICAST,UP,LOWER_UP> 
+
+=== flannel.1 에 주입 — 여기서는 파드 IP 가 보인다 (캡슐화 전) ===
+qdisc prio 1: root refcnt 2 bands 3 priomap 1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
+ Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0) 
+ backlog 0b 0p requeues 0
+qdisc netem 30: parent 1:3 limit 1000 delay 200ms
+ Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0) 
+ backlog 0b 0p requeues 0
+
+=== [검증] 필터에 패킷이 걸리는가 ===
+  qdisc netem 30: parent 1:3 limit 1000 delay 200ms
+   Sent 18388 bytes 150 pkt (dropped 0, overlimits 0 requeues 0) 
+   backlog 0b 0p requeues 0
+
+=== 두 노드 지연 비교 (기준선: k0=70ms k1=66ms) ===
+  keycloak-0  평균 41 ms   최대 57 ms
+  keycloak-1  평균 1872 ms   최대 1887 ms
@@ -0,0 +1,37 @@
+=== 동시 부하 20건을 keycloak-1 에 — 커넥션 풀이 견디는가 ===
+        1 200 1.911191
+        1 200 1.913766
+        1 200 1.958374
+        1 200 1.981620
+        1 200 10.539402
+        1 200 11.951943
+        1 200 13.351102
+        1 200 14.785832
+        1 200 16.189533
+        1 200 17.625166
+        1 200 19.053724
+        1 200 20.495883
+        1 200 21.905932
+        1 200 22.228466
+        1 200 22.230871
+        1 200 3.441366
+        1 200 4.841075
+        1 200 6.257489
+        1 200 7.704608
+        1 200 9.104792
+
+=== 부하 직후 커넥션 풀 ===
+  agroal_blocking_time_max_milliseconds 20000.0
+  agroal_max_used_count 19.0
+  agroal_acquire_count_total 672.0
+  agroal_active_count 0.0
+  agroal_awaiting_count 0.0
+  agroal_blocking_time_average_milliseconds 281.0
+  agroal_available_count 19.0
+
+=== readiness 가 흔들렸는가 ===
+keycloak-0                  1/1   Running   0             60m
+keycloak-1                  1/1   Running   1 (51m ago)   3h24m
+52m         Normal    TaintManagerEviction   pod/keycloak-1                   Cancelling deletion of Pod keycloak-lab/keycloak-1
+32m         Warning   Unhealthy              pod/keycloak-1                   Readiness probe failed: HTTP probe failed with statuscode: 503
+89s         Warning   Unhealthy              pod/keycloak-1                   Readiness probe failed: Get "http://10.42.0.42:9000/health/ready": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
@@ -0,0 +1,12 @@
+=== 지연 해제 ===
+해제완료
+qdisc noqueue 0: root refcnt 2 
+
+=== 회복 확인 ===
+  keycloak-0  평균 43 ms
+  keycloak-1  평균 51 ms
+keycloak-0                  1/1   Running   0             61m
+keycloak-1                  1/1   Running   1 (52m ago)   3h24m
+
+=== 낙관적 락 충돌이 늘었는가 — 지연 중 로그 ===
+  관련 로그 줄수: 0
@@ -0,0 +1,20 @@
+# A-6 — 지연 주입 증거
+
+2026-09-04 13:10–13:35 KST
+해설: [`docs/experiment-a6-latency-injection.md`](../../experiment-a6-latency-injection.md)
+
+| 파일 | 무엇을 보여주는가 |
+|---|---|
+| `01-baseline.txt` | 배치 설명(A/B 가 되는 이유), `agroal_*` 지표 목록, **기준선 70ms / 66ms** |
+| `02-delay-injected.txt` | 첫 시도 실패 — **`Cannot find device "eth0"`** (Debian 은 `enp1s0`) |
+| `03-flannel-injection.txt` | **성공** — `flannel.1` 에 걸어야 파드 IP 가 보인다. netem `Sent 150 pkt` 로 검증. **k0=41ms vs k1=1872ms** |
+| `04-pool-under-load.txt` | 동시 20건 — 응답이 1.9초에서 **22.2초**까지 계단. `blocking_time_max=20000ms`, `max_used_count=19`, **readiness 프로브 타임아웃** |
+| `05-recovery.txt` | 해제 즉시 43ms / 51ms 회복. **낙관적 락 충돌 0건**(예측 빗나감) |
+| `a6-connection-pool-blocking.png` | Grafana — `agroal_blocking_time_max_milliseconds` |
+
+## 핵심 네 줄
+
+1. **200ms 가 1,872ms 가 된다.** 로그인 트랜잭션의 왕복이 9번이라 지연이 곱해진다.
+2. **동시 부하에서 22초까지 늘어난다.** 커넥션 풀 큐잉으로 한 번 더 곱해진다.
+3. **헬스체크도 같은 줄에 선다** — 프로브가 타임아웃되어 노드가 로드밸런서에서 빠지고, 남은 노드로 부하가 몰린다.
+4. **낙관적 락 충돌은 없었다.** 로그인은 새 행을 만들 뿐 같은 행을 다투지 않는다 — B-3 의 영역.