DongHyeonkaandClaude Opus 5
e0d27d47ce
An independent audit found ten documents printing values their evidence files do not contain. C-1 printed a session count of 0 where the evidence says 4, C-2 printed a success readback for a command that exited 1, and A-1 credited the conntrack flush with a split that the timestamps attribute to a pod restart four seconds earlier. Also measured wal_writer_delay, which A-3 had asserted as matching without ever querying it, relabelled the A-6 control that moved 41 percent, noted A-8's nine-sample resolution, corrected D-1's RTO to the 41 seconds its own timeline shows, and added a correction banner to D-2. Every experiment document now links its evidence files with their real collection times, and the duplicate screenshots are documented as duplicates. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
364 lines
13 KiB
Markdown
364 lines
13 KiB
Markdown
# A-6 — 끊기지 않고 느려지기만 하면 어떻게 되는가
|
||
|
||
브랜치 `feature/keycloak-a6-latency-injection` ·
|
||
증거 [`docs/evidence/a6-latency-injection/`](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` 이라는 인터페이스가 없다
|
||
|
||
```bash
|
||
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` 에 건다
|
||
|
||
```bash
|
||
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 ← 기준선 70ms 대비 -41%
|
||
keycloak-1 평균 1872 ms 최대 1887 ms ← 28배
|
||
```
|
||
|
||
> **대조군도 변했다** — keycloak-0 은 기준선 70ms 에서 41ms 로 **41% 빨라졌다.**
|
||
> 주입과 무관한 변동(JIT 워밍업, 캐시)이며, **"영향 없음" 이라고 쓴 것은
|
||
> 부정확했다.** 다만 keycloak-1 의 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
|
||
```
|
||
|
||
> **9 는 SQL 목록을 센 것이고 패킷을 추적한 값이 아니다.** 자릿수가 맞는다는
|
||
> 것까지가 이 계산이 말할 수 있는 범위이며, **왕복 수를 확정하려면
|
||
> `tc -s` 나 패킷 캡처가 필요하다.**
|
||
|
||
> **네트워크 지연은 왕복 횟수만큼 증폭된다.**
|
||
> "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. 복구
|
||
|
||
```bash
|
||
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_*` 은
|
||
있지만 히스토그램이 아니라 평균/최대뿐이다.
|
||
|
||
```promql
|
||
# 있으면 좋았을 것
|
||
histogram_quantile(0.99, rate(http_server_requests_seconds_bucket[5m]))
|
||
```
|
||
|
||
**A-2 에서 `kube-state-metrics` 가 빠진 것을 찾았고, 여기서는 응답 시간
|
||
히스토그램이 빠진 것을 찾았다.** 둘 다 보완 항목이다.
|
||
|
||
---
|
||
|
||
---
|
||
|
||
## 증거 파일
|
||
|
||
**증거 수집 시각: 2026-09-04 13:12 – 13:16 KST** (파일 mtime 기준. 문서 상단의 시각 표기는 작성 시점이라 다를 수 있다.)
|
||
|
||
| 파일 | 종류 |
|
||
|---|---|
|
||
| [`01-baseline.txt`](evidence/a6-latency-injection/01-baseline.txt) | 터미널 원문 |
|
||
| [`02-delay-injected.txt`](evidence/a6-latency-injection/02-delay-injected.txt) | 터미널 원문 |
|
||
| [`03-flannel-injection.txt`](evidence/a6-latency-injection/03-flannel-injection.txt) | 터미널 원문 |
|
||
| [`04-pool-under-load.txt`](evidence/a6-latency-injection/04-pool-under-load.txt) | 터미널 원문 |
|
||
| [`05-recovery.txt`](evidence/a6-latency-injection/05-recovery.txt) | 터미널 원문 |
|
||
| [`a6-connection-pool-blocking.png`](evidence/a6-latency-injection/a6-connection-pool-blocking.png) | 스크린샷 |
|
||
|
||
파일별 상세는 [`evidence/a6-latency-injection/README.md`](evidence/a6-latency-injection/README.md).
|
||
|
||
## 8. 재현 절차 (명령어)
|
||
|
||
```bash
|
||
# 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 앞에 쓴다 |
|
||
| 관측 보완 | **응답 시간 히스토그램**이 없다 |
|
||
| 구성 | **프로브 타임아웃 < 커넥션 풀 대기**여야 격리가 제때 된다 |
|