keycloak-pattern/docs/guides/experiments/a6-latency-injection.md

A-6 재현 가이드 — 끊지 않고 200ms 만 넣어 22초를 만든다

해설 문서: docs/experiment-a6-latency-injection.md · 증거 원문: docs/evidence/a6-latency-injection/

이 가이드가 끝나면

당신 터미널에서 이것들을 직접 본다.

보게 되는 것	어디서
eth0 이라는 인터페이스가 없다는 것	ip -brief link
스크립트가 「적용완료」를 찍었는데 아무것도 안 걸린 것	tc -s qdisc 카운터
enp1s0 에서는 파드 IP 가 안 보이는 것	VXLAN 캡슐화
200ms 가 1,872ms 가 되는 것	두 노드 응답 시간 비교
동시 20건이 22.2초까지 계단으로 늘어나는 것	상주 탐침이 모은 파일
커넥션 획득에 20초를 기다린 요청	agroal_blocking_time_max_milliseconds
readiness 프로브가 같은 줄에 서서 타임아웃되는 것	kubectl get events
예측했던 낙관적 락 충돌이 0건인 것	Keycloak 로그

전제

• 05-keycloak · 06-observability 가 끝나 있다.
• A-5 를 먼저 해 두면 좋다. 「주입을 넣은 것과 걸린 것은 다르다」가 여기서 세 번째로 나온다.
• kubectl 은 kc-lab-1 에서 sudo 로 친다.
• tc 는 kc-lab-2 에서 친다(ssh kc-lab-2). postgres 가 그 노드에 있다.
• 터미널 두 개면 편하다. 하나는 부하·측정, 하나는 이벤트 관찰.

주의 — 이건 상태를 부수는 실험이다

Keycloak 한 대를 느려지게 만든다. 파드가 재시작될 수 있고 readiness 가 빠진다. 실험대에서만 한다. 전 구간 약 30분이다.

중간에 그만두려면 한 줄이면 된다.

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

표시 규약

표시	뜻
실측	2026-09-04 13:10–13:35 KST 실행 기록의 출력 원문. 증거 파일에 그대로 있다
형태	값이 매번 달라지는 출력. 모양만 보이고 숫자는 당신 것과 다르다
미검증	손으로 치기 좋게 이 가이드에서 고친 형태. 원래 실행은 스크립트로 했다

IP·파드 이름·인터페이스 이름은 당신 환경에서 다를 수 있다. 자리표시자 (<...>)를 쓰지 않는 대신, 그 값을 뽑는 명령을 먼저 적는다.

---

0. 왜 이 실험을 하는가

A-2 는 DB 를 완전히 세웠고, A-4 는 기계를 통째로 껐다. 둘 다 즉시 드러났다. 503 이 나오고 up 이 0 이 됐다.

실제 장애의 대부분은 그렇지 않다. 느려지기만 한다. 그리고 느려짐은 사망보다 진단하기 어렵다 — 헬스체크가 통과하기 때문이다.

이 실험이 묻는 것은 하나다.

   200밀리초를 넣으면 애플리케이션은 200밀리초 느려지는가?

답은 아니다. 두 군데에서 곱해진다.

---

1. 설계 — 왜 이 배치가 그대로 A/B 실험이 되는가

1-1. 무엇이 어느 노드에 있나

확인

sudo kubectl -n keycloak-lab get pods -o wide

실측 — 01-baseline.txt

  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 을 건넌다  ← 여기에 지연을 건다

어디를 봐야 하는가 — postgres 와 keycloak-0 이 같은 노드인가.

이 결과가 의미하는 것

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

postgres 가 보내는 패킷 중 노드를 건너가는 것만 지연시키면 keycloak-1 의 DB 접근만 느려지고 keycloak-0 은 그대로다. 대조군이 같은 실험 안에 있다. 파드를 두 개 더 띄울 필요도, 다른 시간대와 비교할 필요도 없다.

배치가 다르면 이 실험은 성립하지 않는다. 두 Keycloak 이 모두 DB 와 다른 노드에 있으면 대조군이 없고, 모두 같은 노드에 있으면 시험군이 없다. 먼저 확인한다.

변수로 잡아 둔다.

K0=$(sudo kubectl -n keycloak-lab get pod keycloak-0 -o jsonpath='{.status.podIP}')
K1=$(sudo kubectl -n keycloak-lab get pod keycloak-1 -o jsonpath='{.status.podIP}')
PG=$(sudo kubectl -n keycloak-lab get pod -l app=postgres -o jsonpath='{.items[0].status.podIP}')
echo "K0=$K0 K1=$K1 PG=$PG"

1-2. 상주 탐침 파드를 먼저 띄운다

Keycloak 컨테이너에는 curl 도 wget 도 없다(exit 127). 그리고 이 실험은 같은 요청을 수십 번 반복해야 하므로 파드를 매번 만들면 안 된다.

하기

sudo kubectl -n keycloak-lab run a6-probe --image=curlimages/curl:8.11.1 \
  --restart=Never \
  --env="K0=$K0" --env="K1=$K1" \
  --env="PW=$(sudo kubectl -n keycloak-lab get secret keycloak-lab-secrets \
              -o jsonpath='{.data.KC_BOOTSTRAP_ADMIN_PASSWORD}' | base64 -d)" \
  --command -- sleep 1800
sudo kubectl -n keycloak-lab wait --for=condition=Ready pod/a6-probe --timeout=120s

되돌리기

sudo kubectl -n keycloak-lab delete pod a6-probe --ignore-not-found

확인 — 값이 들어갔나. 비밀번호는 길이만 본다

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c 'echo "K0=$K0 K1=$K1 PW=${#PW}자"'

형태

K0=10.42.1.77 K1=10.42.0.42 PW=32자

PW=0자 면 시크릿이 안 넘어간 것이다. 그 상태로 재면 전부 401 을 재게 된다.

★ kubectl run --rm -i 로 부하를 주면 안 된다. 원 실행이 그렇게 했다가 동시 20건의 출력을 잃었다. 파드가 만들어지고 지워지는 사이에 stdout 을 붙잡는 경주가 되고, 20줄 중 일부만 도착하거나 아예 끊긴다. 결과는 파드 안 파일에 모으고 끝나면 한 번에 꺼낸다. 이 가이드의 모든 부하 명령이 그 형태다.

탐침의 K0/K1 은 만들 때 고정된다. Keycloak 파드가 재시작되면 IP 가 바뀌고 탐침의 값은 낡는다. 그때는 탐침을 지우고 다시 만든다. 이걸 놓치면 「아무 데도 안 닿음」을 「지연」으로 착각한다.

---

2. 기준선 — 주입 전에 같은 명령으로 먼저 잰다

2-1. 요청 하나를 눈으로 본다

먼저 읽는 형태로 한 번 친다. 시간이 어디서 드는지 봐야 나중에 무엇이 변했는지 안다.

확인

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c '
  curl -s -o /dev/null \
    -w "connect %{time_connect}  ttfb %{time_starttransfer}  total %{time_total}\n" \
    -X POST "http://$K1:8080/realms/master/protocol/openid-connect/token" \
    -d grant_type=password -d client_id=admin-cli -d username=admin -d "password=$PW"'

형태

connect 0.001  ttfb 0.065  total 0.066

어디를 봐야 하는가 — connect 와 ttfb 의 차이.

값	무엇의 시간인가
time_connect	탐침 → Keycloak TCP 연결. 이 실험에서 거의 안 변한다
time_starttransfer	첫 바이트까지 = Keycloak 이 DB 와 대화한 시간. 여기가 폭발한다

이 결과가 의미하는 것 — 지연은 탐침과 Keycloak 사이가 아니라 Keycloak 과 DB 사이에 넣는다. 그래서 connect 는 그대로고 ttfb 만 는다. 주입 후에 이 두 값을 다시 보면 어디에 지연이 걸렸는지 한눈에 판정된다.

응답이 401 이나 400 이면 -o /dev/null 을 빼고 본문을 본다.

2-2. 반복해서 평균을 낸다

확인 — 20회, 원본을 파일에 모은다

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c '
  rm -f /tmp/base-k1 ; i=0
  while [ $i -lt 20 ]; do
    curl -s -o /dev/null -w "%{time_total}\n" \
      -X POST "http://$K1:8080/realms/master/protocol/openid-connect/token" \
      -d grant_type=password -d client_id=admin-cli -d username=admin -d "password=$PW" \
      >> /tmp/base-k1
    i=$((i+1))
  done'

원본을 먼저 본다. 평균만 보면 한 건이 튄 것을 놓친다.

sudo kubectl -n keycloak-lab exec a6-probe -- cat /tmp/base-k1

그 다음 줄여서 본다.

sudo kubectl -n keycloak-lab exec a6-probe -- cat /tmp/base-k1 \
  | awk '{s+=$1} END {printf "%d회 평균 %.0f ms\n", NR, s*1000/NR}'

$K1 을 $K0 로 바꿔 대조군도 똑같이 잰다.

실측 — 01-baseline.txt

=== 기준선 지연 — 각 노드에서 로그인 20회 ===
  keycloak-0  평균 70 ms
  keycloak-1  평균 66 ms

어디를 봐야 하는가 — 두 값이 비슷한 것. 지금 keycloak-1 이 오히려 4ms 빠르다. VXLAN 을 건너는 쪽이 더 빠를 수도 있는 수준의 차이이며, 그래서 뒤에 나올 28배가 의심의 여지 없이 주입 탓이 된다.

횟수를 주입 전후로 똑같이 맞춘다. 기준선은 20회로 쟀고, 해설 문서의 재현 절차에는 15회로 적혀 있다. 횟수가 다르면 평균도 달라진다. 비교할 두 값은 같은 명령으로 만든다.

2-3. 커넥션 풀 지표에 무엇이 있나

확인

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c \
  'curl -s "http://$K1:9000/metrics" | grep "^agroal_"'

실측 — 01-baseline.txt

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

어디를 봐야 하는가 — agroal_* 이 JDBC 커넥션 풀 지표다 (Agroal 은 Quarkus 의 풀 구현이다). 이 실험의 핵심 증거가 여기서 나온다.

당신 출력은 이보다 길 것이다. 위 목록은 알파벳순으로 destroy_count_total 에서 끊겨 있다 — 원 실행이 앞부분만 남긴 것이다. 실제로는 뒤에 agroal_max_used_count 같은 것이 더 있고, 6-4 에서 그 값을 쓴다. 증거 파일이 짧다고 지표가 없는 것이 아니다.

지표	무엇을 말하는가
blocking_time_max	커넥션을 받으려고 가장 오래 기다린 시간
max_used_count	풀이 최대 몇 개까지 늘었나
awaiting_count	지금 줄 서 있는 요청 수
active_count	지금 쓰이고 있는 커넥션 수

awaiting_count 와 active_count 는 순간값이다. 부하가 끝나면 0 으로 돌아간다 — 부하 중에 읽어야 보인다. blocking_time_max 는 누적이라 나중에 읽어도 남아 있다.

지금 값을 적어 둔다. 나중에 오른 것을 보려면 지금 값이 필요하다.

---

3. 주입 시도 ① — eth0 (그런 인터페이스가 없다)

일부러 실패하는 단계다. 이 실패의 모양이 이 실험이 남긴 가장 실용적인 교훈이다.

3-1. 넣어 본다

하기

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

실측 — 02-delay-injected.txt

Cannot find device "eth0"

한 줄이면 끝날 일이다. 그런데 원 실행은 이걸 스크립트로 돌렸다.

실측 — 같은 파일, 원문 그대로

=== 주입: 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

어디를 봐야 하는가 — 적용완료 가 에러 사이에 끼어 있다.

이 결과가 의미하는 것 — 「적용완료」는 스크립트가 찍은 글자이지 커널이 한 말이 아니다. tc 는 네 번 다 실패했는데 스크립트는 그대로 다음 절로 넘어갔고, 문서에는 시각까지 찍혔다.

명령의 성공을 「에러가 안 보인다」로 판정하면 안 된다. 에러는 보였는데 그 사이에 성공 메시지가 있었을 뿐이다. 손으로 한 줄씩 치면 이 실수를 할 수 없다 — 이 가이드에 스크립트가 없는 이유다.

그리고 그 상태에서 잰 「검증」이 이랬다.

실측 — 같은 파일

=== [검증] 지연이 실제로 걸렸는가 — 두 노드 비교 ===
  keycloak-0  평균 43 ms   최대 64 ms
  keycloak-1  평균 47 ms   최대 70 ms

두 노드가 여전히 같다. 이것이 「안 걸렸다」는 신호였다. 검증 절이 값을 찍기만 하고 판정하지 않으면 이렇게 그냥 지나간다.

3-2. 인터페이스 이름을 확인한다

확인

ssh kc-lab-2 'ip -brief link'

실측 — 03-flannel-injection.txt

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>

게스트의 물리 인터페이스는 enp1s0 이다.

어디를 봐야 하는가 — eth0 이 없다.

이름	무엇
enp1s0	게스트의 물리(가상) NIC. 노드 간 실제 트래픽이 나가는 곳
flannel.1	VXLAN 터널. 노드를 건너는 파드 트래픽이 여기로 들어간다
cni0	노드 안 브리지. 같은 노드 파드끼리는 여기서 끝난다

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

   enp1s0
   │ │  └─ s0 : slot 0
   │ └──── p1 : PCI bus 1
   └────── en : ethernet

이름이 하드웨어 위치에서 나오므로 NIC 순서가 바뀌어도 이름이 안 바뀐다. 그 대신 eth0 이라고 적힌 인터넷의 모든 예제가 안 돈다.

flannel.1 의 상태가 UNKNOWN 인 것은 정상이다. 터널 장치는 캐리어 개념이 없어서 UP 대신 UNKNOWN 으로 보고한다. 고장이 아니다.

---

4. 주입 시도 ② — enp1s0 (파드 IP 가 안 보인다)

eth0 을 enp1s0 으로 고치면 될 것 같다. 안 된다. 이유가 이 실험의 핵심 개념이다.

4-1. 무엇이 문제인가

노드 간 파드 통신은 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 만 있다.

4-2. 눈으로 확인한다

확인 — 실제로 무엇이 나가는지 본다. 미검증

ssh kc-lab-2 'sudo tcpdump -i enp1s0 -n -c 5 udp port 8472'

노드 IP 사이의 UDP 8472 만 보이고 10.42.x.x 는 안 보인다.

같은 시간에 터널 쪽을 보면 파드 IP 가 보인다. 미검증

ssh kc-lab-2 'sudo tcpdump -i flannel.1 -n -c 5 host 10.42.1.76'

원 실행에는 이 확인이 없다. eth0 실패 뒤 곧바로 flannel.1 로 갔다. 그래서 「enp1s0 에 걸면 0 패킷」이라는 출력 원문은 이 실험에 없다 — 구조에서 나온 결론이다. 당신이 직접 보고 싶으면 위 tcpdump 두 줄이면 된다.

이 결과가 의미하는 것 — 오버레이 네트워크에서는 「어느 인터페이스에 거는가」가 「무엇을 볼 수 있는가」를 정한다.

인터페이스	파드 IP 가 보이나	무엇을 지연시키게 되나
cni0	보인다	같은 노드 안 통신만
flannel.1	보인다 (캡슐화 직전)	노드를 건너는 파드 통신
enp1s0	안 보인다	노드 간 모든 것 (SSH·k3s 포함)

enp1s0 에 netem 을 root 로 걸면 kubectl 도 SSH 도 같이 느려진다. 그러면 무엇이 원인인지 못 가린다.

---

5. 주입 성공 — flannel.1 에 건다

5-1. 거는 순서

되돌리기 — 먼저 읽어 둔다. 이 한 줄이 세 가지를 다 지운다

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

하기

ssh kc-lab-2 "sudo tc qdisc add dev flannel.1 root handle 1: prio"
ssh kc-lab-2 "sudo tc qdisc add dev flannel.1 parent 1:3 handle 30: netem delay 200ms"
ssh kc-lab-2 "sudo tc filter add dev flannel.1 protocol ip parent 1:0 prio 3 \
     u32 match ip src $PG/32 flowid 1:3"
date '+%H:%M:%S 주입'

한 줄씩 친다. 앞 줄이 실패하면 뒤 줄은 붙을 곳이 없어서 다른 에러를 낸다.

5-2. 개념 — tc 의 계층 구조

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

netem 을 root 에 바로 붙이면 모든 트래픽이 느려진다. prio + filter 를 쓰면 고른 트래픽만 느려진다. 이 실험은 postgres 가 보내는 것만 골라야 하므로 세 단계가 필요하다.

세 줄이 하는 일을 나눠 읽으면 이렇다.

줄	하는 일
qdisc ... root handle 1: prio	밴드 3개짜리 분류기를 만든다
qdisc ... parent 1:3 handle 30: netem delay 200ms	3번 밴드에 200ms 지연을 붙인다
filter ... match ip src $PG/32 flowid 1:3	출발지가 postgres 인 패킷을 3번 밴드로 보낸다

5-3. ★ 걸렸는지 카운터로 확인한다 — 그리고 0 을 오해하지 않는다

확인

ssh kc-lab-2 'sudo tc -s qdisc show dev flannel.1'

실측 — 03-flannel-injection.txt · 넣은 직후

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

Sent 0 pkt 이다. 그런데 이건 실패가 아니다.

A-5 에서 pkts 0 은 「규칙이 안 걸렸다」였다. 여기서는 다르다 — 아직 아무 패킷도 지나가지 않았을 뿐이다. postgres 는 요청이 있어야 답한다.

하기 — 트래픽을 한 번 만든다

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c '
  curl -s -o /dev/null -w "%{time_total}\n" \
    -X POST "http://$K1:8080/realms/master/protocol/openid-connect/token" \
    -d grant_type=password -d client_id=admin-cli -d username=admin -d "password=$PW"'

확인 — 다시 센다

ssh kc-lab-2 'sudo tc -s qdisc show dev flannel.1 | grep -A2 netem'

실측 — 같은 파일

=== [검증] 필터에 패킷이 걸리는가 ===
  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

어디를 봐야 하는가 — 150 pkt. 실제로 지연 밴드를 통과했다.

판정표 — netem 의 Sent

상태	뜻	할 일
부하 전 0 pkt	아직 트래픽이 없다	요청을 한 번 보내고 다시 센다
부하 후에도 0 pkt	필터가 아무것도 못 잡았다	IP·인터페이스·방향을 다시 본다
pkt 이 는다	걸렸다	관찰로 넘어간다
dropped 가 는다	limit 1000 을 넘겼다	부하를 줄이거나 limit 을 올린다

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

필터 자체도 볼 수 있다. 미검증

ssh kc-lab-2 'sudo tc filter show dev flannel.1'

---

6. 효과를 관찰한다

6-1. 단일 요청 — 지연은 곱해진다

확인 — 2-1 과 똑같은 명령을 다시 친다

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c '
  curl -s -o /dev/null \
    -w "connect %{time_connect}  ttfb %{time_starttransfer}  total %{time_total}\n" \
    -X POST "http://$K1:8080/realms/master/protocol/openid-connect/token" \
    -d grant_type=password -d client_id=admin-cli -d username=admin -d "password=$PW"'

connect 는 그대로인데 ttfb 만 폭발하는지 본다. 그러면 지연이 의도한 구간에 걸린 것이다.

그 다음 2-2 와 똑같이 반복해서 두 노드를 잰다.

실측 — 03-flannel-injection.txt

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

어디를 봐야 하는가 — keycloak-1 이 66 → 1,872 ms, 28배.

★ 대조군도 변했다. keycloak-0 은 기준선 70ms 에서 41ms 로 41% 빨라졌다. 주입과 무관한 변동(JIT 워밍업, 캐시)이며, 해설 문서가 처음에 「영향 없음」이라고 쓴 것은 부정확했다. 자릿수가 달라 결론은 유지되지만, 대조군이 안 변한다고 가정하면 안 된다. 당신 실행에서도 볼 것이다.

6-2. 왜 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

★ 9 는 SQL 목록을 센 것이고 패킷을 추적한 값이 아니다. 자릿수가 맞는다는 것까지가 이 계산이 말할 수 있는 범위이며, 왕복 수를 확정하려면 tc -s 의 패킷 수를 요청 수로 나누거나 패킷 캡처가 필요하다.

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

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

여기가 이 실험의 본 시험이다. 순차로 20번 돌리면 큐잉이 재현되지 않는다. 동시에 20건을 보내야 한다.

하기 — 백그라운드로 띄우고 wait. 결과는 파드 안 파일에 모은다

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c '
  rm -f /tmp/load ; i=0
  while [ $i -lt 20 ]; do
    ( curl -s -o /dev/null -w "%{http_code} %{time_total}\n" --max-time 60 \
        -X POST "http://$K1:8080/realms/master/protocol/openid-connect/token" \
        -d grant_type=password -d client_id=admin-cli -d username=admin -d "password=$PW" \
      >> /tmp/load ) &
    i=$((i+1))
  done
  wait'

확인 — 다 모였는지부터 센다

sudo kubectl -n keycloak-lab exec a6-probe -- cat /tmp/load > /tmp/load.txt
wc -l /tmp/load.txt

20 이 아니면 수집이 샌 것이다. 그 상태의 숫자는 해석하지 않는다.

확인 — 원본을 본다

cat /tmp/load.txt

그 다음 상태 코드와 시간을 나눠 본다.

awk '{print $1}' /tmp/load.txt | sort | uniq -c
awk '{print $2}' /tmp/load.txt | sort -g

실측 — 04-pool-under-load.txt

=== 동시 부하 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

어디를 봐야 하는가 — 두 가지다.

① 순서가 이상하다. 10.5 가 3.4 보다 앞에 있다. 원 실행이 sort 를 사전순으로 썼기 때문이다(맨 앞의 1 은 uniq -c 가 붙인 개수다). 문자열로 정렬하면 "10.5" < "3.4" 다.

sort  /tmp/load.txt      # 사전순 — 10.5 가 3.4 앞에 온다
sort -g /tmp/load.txt    # 수치순 — 이걸 써야 한다

시간 값을 정렬할 때는 sort -g. 이걸 놓치면 「최대값」을 잘못 읽는다.

② 숫자를 순서대로 놓으면 계단이다.

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

전부 성공(200)했지만 응답 시간이 1.9초에서 22.2초까지 늘어난다. 전형적인 큐잉이다. 커넥션 수는 유한하고, 각 요청이 커넥션을 1.9초씩 붙잡으므로 뒤에 온 요청은 그만큼 기다린다.

200 만 보는 감시는 이 장애를 못 본다. 상태 코드는 전부 정상이다. 응답 시간 분포를 봐야 한다.

6-4. 커넥션 풀 지표가 증언한다

부하가 끝나자마자 읽는다. 늦으면 순간값이 0 으로 돌아간다.

확인

sudo kubectl -n keycloak-lab exec a6-probe -- sh -c \
  'curl -s "http://$K1:9000/metrics" | grep -E "^agroal_(blocking_time|max_used|acquire|active|available|awaiting)"'

실측 — 04-pool-under-load.txt

=== 부하 직후 커넥션 풀 ===
  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

어디를 봐야 하는가

값	읽는 법
blocking_time_max 20000.0	커넥션을 받으려고 20초를 기다린 요청이 있었다
max_used_count 19.0	풀이 19개까지 늘어났다
blocking_time_average 281.0	평균은 0.3초. 평균만 보면 아무 일도 없어 보인다
active_count 0.0 · awaiting_count 0.0	순간값. 부하가 끝나서 0 이다

평균과 최대의 간격이 이 장애의 모양이다. 평균 281ms 짜리 그래프에서는 아무도 20초를 보지 못한다.

Grafana 에서 같은 것을 그림으로 본다 — a6-connection-pool-blocking.png.

6-5. 그리고 헬스체크가 무너진다

확인

sudo kubectl -n keycloak-lab get events --sort-by=.lastTimestamp | tail -20
sudo kubectl -n keycloak-lab get pods

실측 — 04-pool-under-load.txt

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)

어디를 봐야 하는가 — 89s 짜리 줄. 그것이 지금 주입의 결과다. 32m·52m 짜리는 A-4 의 잔재다(노드를 껐다 켠 흔적).

이벤트를 볼 때는 Age 를 먼저 본다. 이벤트 목록은 한 시간 전 것까지 섞여 있다. 방금 일어난 일만 골라야 한다.

두 실패의 차이가 중요하다.

메시지	무슨 일
HTTP probe failed with statuscode: 503	Keycloak 이 답은 했다. 스스로 DOWN 이라고 말했다
context deadline exceeded	답 자체를 못 했다. 프로브가 줄에서 기다리다 끝났다

readiness 프로브 자체가 타임아웃됐다. 헬스체크도 같은 커넥션 풀 줄에 선다.

6-6. 연쇄 고장의 모양

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

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

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

계획서에는 이렇게 적혀 있었다.

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

확인 — 지연 구간의 로그를 센다. 미검증 (원 실행의 정확한 패턴은 기록에 없다)

sudo kubectl -n keycloak-lab logs keycloak-1 --since=20m \
  | grep -icE 'optimistic|StaleState|version.*conflict'

실측 — 05-recovery.txt

=== 낙관적 락 충돌이 늘었는가 — 지연 중 로그 ===
  관련 로그 줄수: 0

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

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

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

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

---

7. 복구

7-1. 지운다

하기

date '+%H:%M:%S 해제'
ssh kc-lab-2 'sudo tc qdisc del dev flannel.1 root'

확인

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

실측 — 05-recovery.txt

=== 지연 해제 ===
해제완료
qdisc noqueue 0: root refcnt 2

어디를 봐야 하는가 — noqueue. prio 도 netem 도 없다. root 를 지우면 그 아래 자식 qdisc 와 filter 가 같이 사라진다.

7-2. 즉시 회복하는지 본다

확인 — 2-2 의 반복 측정 명령을 그대로 다시 친다. 그 명령의 첫 줄이 rm -f /tmp/base-k1 이므로 파일은 새로 만들어진다. 두 노드 다 잰다.

같은 명령이어야 비교가 된다. 다른 명령으로 잰 값은 기준선과 나란히 놓을 수 없다.

실측 — 같은 파일

=== 회복 확인 ===
  keycloak-0  평균 43 ms
  keycloak-1  평균 51 ms
keycloak-0                  1/1   Running   0             61m
keycloak-1                  1/1   Running   1 (52m ago)   3h24m

파드 재시작 없이 즉시 회복. RESTARTS 가 안 늘었다 — 이 실험은 readiness 를 흔들었을 뿐 파드를 죽이지는 않았다. 커넥션 풀도 스스로 정상화됐다.

7-3. 원상복구 확인표

항목	명령	돌아왔을 때
qdisc	ssh kc-lab-2 'sudo tc qdisc show dev flannel.1'	noqueue
(물리 쪽도)	ssh kc-lab-2 'sudo tc qdisc show dev enp1s0'	시도 ① 잔재가 없어야 한다
응답 시간	2-2 의 반복 측정	기준선과 같은 자릿수
파드	sudo kubectl -n keycloak-lab get pods	둘 다 1/1 Running
Service	sudo kubectl -n keycloak-lab get endpointslice -l kubernetes.io/service-name=keycloak	ready 주소 둘
풀	agroal_awaiting_count · agroal_active_count	0
탐침 파드	sudo kubectl -n keycloak-lab get pod a6-probe	지웠으면 NotFound
밖	curl -s -o /dev/null -w '%{http_code}\n' https://auth.hyeonworks.com/realms/master	200

탐침을 지운다.

sudo kubectl -n keycloak-lab delete pod a6-probe --ignore-not-found

agroal_blocking_time_max_milliseconds 는 누적이라 20000 인 채로 남는다. 파드를 재시작해야 0 이 된다. 그대로 두는 편이 낫다 — 「이 노드가 한 번 20초를 기다린 적이 있다」는 기록이다.

---

막히면

전부 이 실험대가 실제로 겪은 증상이다. 지어낸 것은 없다.

증상	원인	확인
Cannot find device "eth0"	이 게스트의 NIC 는 enp1s0 이다	ip -brief link — 3-2
스크립트가 「적용완료」인데 지연이 없다	성공 메시지는 스크립트가 찍은 것	tc -s qdisc 카운터 — 3-1
enp1s0 에 걸었는데 안 걸린다	VXLAN 안에 파드 IP 가 숨어 있다	flannel.1 에 건다 — 4절
Sent 0 pkt	부하 전이면 정상. 부하 후면 필터가 틀렸다	요청 한 번 보내고 다시 센다 — 5-3
지연이 양쪽 다 늘었다	netem 을 root 에 직접 붙였다	prio + filter 로 골라 낸다 — 5-2
kubectl 이나 SSH 까지 느려졌다	enp1s0 에 걸었다	tc qdisc del dev enp1s0 root
20줄 중 몇 줄만 온다	kubectl run --rm -i 로 동시 실행하면 stdout 이 샌다	상주 파드 + 파일 — 1-2
최대값이 9.1 로 보인다	sort 가 사전순이다	sort -g — 6-3
blocking_time 이 0 이다	부하가 끝나고 한참 뒤에 읽었다	부하 직후에 읽는다 — 6-4
awaiting_count 가 늘 0 이다	순간값이다	부하가 도는 중에 읽는다
로그인이 전부 401	PW 가 안 넘어갔다	exec a6-probe -- sh -c 'echo ${#PW}' — 1-2
갑자기 아무 데도 안 닿는다	파드 IP 가 바뀌었다	탐침을 지우고 다시 만든다 — 1-2
이벤트가 과거 것과 섞인다	이벤트는 한 시간 전 것도 남는다	Age 를 먼저 본다 — 6-5
대조군도 값이 변했다	정상이다. JIT·캐시 변동	자릿수로 판정한다 — 6-1
dropped 가 늘어난다	netem 의 limit 1000 을 넘겼다	부하를 줄이거나 limit 을 올린다

---

이 실험이 남기는 관측 숙제

지금 관측 스택에는 지연 분포 지표가 없다. agroal_blocking_time_* 은 있지만 히스토그램이 아니라 평균과 최대뿐이다. 6-4 에서 본 대로 평균 281ms 와 최대 20,000ms 사이에 무엇이 있었는지는 알 수 없다.

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

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

---

다음

실험	A-6 이 남긴 질문
B-3 refresh 경쟁	지연을 함께 주면 낙관적 락 충돌이 재현될 것 — 여기서는 안 됐다
B-1 저장소 지연	같은 기법을 Redis 앞에 쓴다. flannel.1 · prio · filter 그대로
A-4 노드 상실	거기서는 up=0 이 정확했다. 여기서는 up=1 인 채로 무너진다
관측 보완	응답 시간 히스토그램이 없다
전부	주입이 걸렸는지 카운터로 먼저 확인한다. 세 실험 연속으로 같은 교훈