document-haness/docs/keycloak-session-store/tech-log-studio/losing-a-node-or-the-store/case/case-200ms-of-delay-became-22-seconds.md

kind, slug, title, topic, topicName, project, status, lastVerifiedOn, sourceRevision, source, assets, evidence

kind	slug	title	topic	topicName	project	status	lastVerifiedOn	sourceRevision	source	assets	evidence
CASE	200ms-of-delay-became-22-seconds	200 밀리초를 넣었더니 응답이 22.2 초가 됐다	losing-a-node-or-the-store	PostgreSQL 을 내리고 노드 전원을 뽑았을 때	keycloak-session-store	게시 전	2026-09-04	cdac9b8178391311d8eca1ebc6cac15bb62d79af	final/document.md#선택의-이유와-지킨-경계-a6	key file a6-latency-multiplication ../../../final/assets/a6-latency-multiplication/a6-latency-multiplication.svg	../../../final/evidence/raw/a6-latency-injection__02-delay-injected.txt ../../../final/evidence/raw/a6-latency-injection__04-pool-under-load.txt

200 밀리초를 넣었더니 응답이 22.2 초가 됐다

데이터베이스 패킷에 200 밀리초를 더했더니 로그인 응답이 66 밀리초에서 1,872 밀리초가 됐고, 동시 20 건에서는 가장 느린 요청이 22.2 초에 끝났다. 왕복마다 지연이 더해지고 그 뒤에 커넥션 풀 대기가 한 번 더 곱한다. 커넥션 획득 대기는 최대 20,000 밀리초였고 readiness 프로브도 같은 줄에 서서 타임아웃됐다.

관계

• readiness 가 깨진 노드를 시야에서 먼저 치운다 여기서 관측한 것은 프로브가 타임아웃된 것까지다. 그 뒤에 노드가 어떻게 치워지는지는 그 기록이 다룬다.
• 노드를 잃는 두 가지 — 저장소가 같이 죽는 것과 들어갈 길이 없는 것 거기서는 노드를 통째로 끊었고 여기서는 노드 사이를 느리게만 만들었다. 느리게 만든 쪽도 헬스체크를 무너뜨리는 데까지는 닿았다.

문제

이 실험대는 Keycloak 두 대 가운데 하나만 데이터베이스와 같은 노드에 있다. kc-lab-2 의 keycloak-0 은 노드 안에서 PostgreSQL 에 닿고, kc-lab-1 의 keycloak-1 은 노드 사이를 건넌다.

노드 사이가 느려지면 세션을 데이터베이스에 두는 구성이 얼마나 느려지는지, 그리고 느려지기만 하는지 아니면 장애가 되는지를 재야 했다. 그 전에 예측을 두 개 적었다. 응답이 넣은 지연만큼 늘 것이고, 동시 로그인이 몰리면 낙관적 락 충돌이 보일 것이라고.

결론

넣은 지연 : 200 밀리초 로그인 응답 : 66 밀리초에서 1,872 밀리초로 · 28 배 동시 20 건에서 가장 느린 응답 : 22.2 초 동시 20 건 전부 200 : o 커넥션 획득 대기 최대 : 20,000 밀리초 readiness 프로브 : 타임아웃으로 실패한 이벤트가 찍혔다 파드 재시작 : 0 회. 서비스에서 빠졌는지는 재지 않았다 낙관적 락 충돌 : 0 건

28 배는 한 번에 생기지 않는다. 로그인 한 번이 데이터베이스를 여러 번 왕복하므로 200 밀리초가 왕복 횟수만큼 더해진다. 22.2 초는 거기서 한 단계 더 간 값이다. 길어진 요청이 커넥션을 붙들고 있는 동안 뒤의 요청이 풀에서 기다리고, 그 대기가 응답 시간에 더해진다.

느림은 헬스체크까지 닿았다. readiness 프로브가 정해진 시간 안에 답을 못 받아 실패 이벤트가 찍혔다. 그 다음에 오는 「노드가 서비스에서 빠진다」는 쿠버네티스가 그렇게 하도록 되어 있는 동작이지 이 실험에서 확인한 것이 아니다.

예측 두 개 가운데 하나는 틀렸다. 낙관적 락 충돌은 0 건이었다. 로그인은 세션 행을 INSERT 하지 UPDATE 하지 않아서 경합할 대상이 없다.

검증 환경

클러스터 : k3s · 노드 둘 keycloak-0 : kc-lab-2 · PostgreSQL 과 같은 노드 keycloak-1 : kc-lab-1 · 노드 사이를 건넌다 커넥션 풀 : agroal · Quarkus 의 JDBC 풀이라 지표 이름이 agroal 로 시작한다 지연을 건 대상 : PostgreSQL 이 보내는 패킷 지연을 건 인터페이스 : flannel.1 · VXLAN 캡슐화 전이라 파드 주소가 보인다 주입 값 : 200 밀리초 한 점

측정일 : 2026-09-04 13:10–13:35 KST

재현 조건

1. 데이터베이스와 같은 노드에 있는 Keycloak 과 다른 노드에 있는 Keycloak 을 함께 둔다. 한쪽만 느려져야 그 차이를 지연 탓으로 돌릴 수 있다.

2. 주입 전에 두 노드에서 로그인을 20 회씩 걸어 평균 응답 시간을 적어 둔다.

3. 데이터베이스가 보내는 패킷에만 200 밀리초를 더한다. 물리 인터페이스에 걸면 안 된다. flannel VXLAN 이 이미 캡슐화해서 파드 주소가 헤더에 없다. flannel.1 에 건다.

4. 주입이 실제로 걸렸는지 결과와 따로 확인한다. 큐 규칙에 패킷이 잡혔는지 보고, 두 노드의 로그인 응답 시간이 갈라졌는지 본다. 갈라지지 않았으면 주입이 안 걸린 것이다.

5. 노드를 건너는 쪽으로 로그인 한 건을 보내 응답 시간을 잰다.

6. 같은 노드로 동시 20 건을 보내고 20 건 전부의 상태 코드와 응답 시간을 받는다. 일회성 파드로 띄우면 출력이 유실된다. 상주 탐침에서 파일로 모은다.

7. 부하 직후 커넥션 풀 지표를 읽는다. 획득 대기 최대 : agroal_blocking_time_max_milliseconds 최대로 쓴 커넥션 수 : agroal_max_used_count

8. 파드 이벤트에서 readiness 프로브가 실패했는지 확인한다. 이벤트는 한 시간 전 것까지 섞여 있으므로 Age 를 먼저 보고 이번 주입의 것만 고른다. 서비스에서 빠졌는지까지 보려면 엔드포인트 목록을 부하 중에 따로 읽어야 한다.

9. 지연을 풀고 두 노드의 응답 시간이 돌아오는지 본다.

본문

한쪽만 노드를 건넌다

Keycloak 은 두 대다. kc-lab-2 의 keycloak-0 은 PostgreSQL 과 같은 노드에 있어 노드 안에서 데이터베이스에 닿고, kc-lab-1 의 keycloak-1 은 노드 사이를 건넌다. 데이터베이스가 보내는 패킷에만 지연을 걸면 keycloak-1 만 느려지고 keycloak-0 은 그대로이므로, 두 값의 차이를 지연 탓으로 돌릴 수 있다.

주입 전에 keycloak-1 의 로그인 응답은 66 밀리초였다.

처음 건 지연은 걸리지 않았다

지연은 리눅스 트래픽 제어로 걸었다. 큐 규칙을 밴드로 나누고 출발지 주소가 PostgreSQL 인 패킷만 지연 밴드로 보내는 방식인데, 처음 지정한 인터페이스는 인터넷 예제가 전부 쓰는 eth0 이었고 명령이 장치를 찾지 못했다.

명령을 한 줄씩 치지 않고 스크립트로 묶어 돌린 탓에 그 실패가 그대로 지나갔다. tc 는 네 번 다 실패했는데 스크립트는 그 사이에 자기가 찍는 적용완료 를 끼워 넣고 주입 시각 13:14:55 까지 남긴 뒤 다음 절로 넘어갔다.

  keycloak-0  평균 43 ms   최대 64 ms
  keycloak-1  평균 47 ms   최대 70 ms

두 노드가 갈리지 않았다. 이 결과는 「지연을 넣어도 영향이 없다」와 구별되지 않는다. 이 실험대에서 주입은 아홉 번 조용히 실패했고, 그래서 주입한 다음 대상이 실제로 그 상태인지를 결과와 따로 확인하는 단계를 모든 실험에 두었다.

걸리지 않은 이유가 둘이었다. 하나는 배포판 차이로, Debian 게스트의 인터페이스 이름이 eth0 이 아니라 enp1s0 이다. 다른 하나는 오버레이 네트워크다. flannel 은 VXLAN(Virtual Extensible LAN) 으로 파드 사이 통신을 UDP 로 감싸 노드 사이를 건네므로 물리 인터페이스에서 보면 노드 주소 사이의 UDP 패킷이고 안쪽 파드 주소는 캡슐 안에 있다. 출발지가 PostgreSQL 인 패킷을 고르는 필터는 문법상 유효한 채로 영원히 0 건을 잡는다. 캡슐화 전인 flannel.1 에서 걸어야 안쪽 주소가 보인다.

둘째 이유는 enp1s0 로 이름만 고쳤을 때 벌어졌을 일이고, 캡슐화 구조에서 나온 결론이다. 원 실행은 eth0 이 실패한 뒤 곧바로 flannel.1 로 갔으므로, enp1s0 에서 필터가 0 건을 잡는 것을 본 출력은 이 실험에 없다.

로그인 한 건이 28 배가 됐다

flannel.1 에 다시 걸고 나서 keycloak-1 의 로그인 응답이 66 밀리초에서 1,872 밀리초가 됐다. 넣은 값은 200 밀리초인데 응답은 28 배다.

로그인 한 번이 데이터베이스 왕복 한 번으로 끝나지 않기 때문이다. 왕복마다 200 밀리초가 붙고 그 합이 응답 시간이 되므로, 66 밀리초가 1,872 밀리초가 된 것은 그 왕복이 여러 번이었다는 뜻이다. 로그인 하나가 왕복을 정확히 몇 번 하는지는 이 실험에서 세지 않았다.

같은 비교에 대조군도 함께 찍혀 있었다. 지연을 걸지 않은 keycloak-0 은 주입 전 70 밀리초에서 41 밀리초로 내려갔는데, 처음 적을 때는 그것을 「영향 없음」이라고 적었다. −41% 움직인 대조군은 영향 없음이 아니다. 그 −41% 자체는 주입과 무관한 변동이고 JIT 워밍업과 캐시가 그만큼을 움직였다. 28 배와 자릿수가 달라 결론은 그대로 서는데, 판정을 자릿수로 한 것이지 대조군이 안 변해서가 아니다. 이 실험대에서 대조군 없이 귀속하지 않는다는 규칙을 어긴 곳이 둘인데 그중 하나가 여기이고, 나중에 고쳤다.

동시 20 건에서 22.2 초

같은 노드로 동시에 20 건을 보냈다. 20 건 전부 200 을 받았는데 응답 시간이 1.9 초에서 22.2 초까지 벌어졌다.

동시 20 건 중 어느 요청인가	로그인 응답 시간
먼저 커넥션을 잡은 네 건	1.911 · 1.913 · 1.958 · 1.981 초
그 뒤 열네 건	3.441 초부터 21.905 초까지 약 1.4 초 간격
마지막 두 건	22.228 · 22.230 초

앞의 네 건은 앞 절의 1,872 밀리초와 같은 크기다. 나머지 열여섯 건은 커넥션이 비기를 기다렸고, 기다린 시간이 응답 시간에 그대로 더해졌다. 약 1.4 초 간격으로 한 건씩 빠져나오는 계단 모양이 그 대기다.

Keycloak 이 쓰는 커넥션 풀은 Quarkus 의 JDBC 풀인 Agroal 이라 지표 이름이 agroal_ 로 시작한다. 부하가 끝나자마자 상주 탐침에서 keycloak-1 의 지표를 읽었다.

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)"'

그 명령이 낸 값은 이렇다.

  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

커넥션을 받으려고 가장 오래 기다린 요청은 20,000 밀리초를 기다렸고, 최대로 쓴 커넥션은 19 개, 평균 대기는 281 밀리초였다. active_count 와 awaiting_count 가 0 인 것은 두 지표가 순간값이기 때문이다. 각각 지금 쓰이는 커넥션 수와 지금 줄 선 요청 수를 세므로, 부하가 끝난 뒤에 읽으면 0 이 나온다. blocking_time_max 는 누적이라 나중에 읽어도 20,000 이 남아 있다. 그 사이가 어떤 모양이었는지는 이 기록이 대지 못한다. 관측 스택에 히스토그램 지표가 없어서 281 밀리초와 20,000 밀리초 사이의 분포가 안 남았다.

주입하지 않은 상태에서 동시 20 건을 걸어 같은 지표를 읽은 값은 이 실험에 없다. 주입 전 측정은 로그인을 한 건씩 차례로 20 회 보낸 것이라 커넥션을 두고 다투는 요청이 없었다.

넣은 지연과 22.2 초 사이에는 단계가 둘이다. 왕복마다 더해지는 것과 풀에서 기다리는 것 중 하나만 보면 28 배도 22.2 초도 계산되지 않는다.

헬스체크도 같은 줄에 섰다

부하를 건 뒤 파드 상태와 이벤트 목록을 함께 읽었다.

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 짜리 두 줄은 이번 주입이 아니라 앞서 노드를 껐다 켠 실험이 남긴 것이고, 파드의 RESTARTS 가 1 (51m ago) 인 것도 같은 흔적이다. 이벤트 목록에는 한 시간 전 것까지 남으므로 Age 를 먼저 보고 이번 주입의 것만 고른다.

실패한 방식도 둘이 다르다. 32m 짜리는 상태 코드 503 이라 Keycloak 이 답은 하면서 스스로 DOWN 이라고 말한 것이고, 89s 짜리는 context deadline exceeded 로 답 자체를 못 한 것이다.

readiness 가 계속 실패하면 쿠버네티스가 그 파드를 서비스 엔드포인트에서 빼고, 그러면 밖에서는 느린 노드가 아니라 노드 하나가 사라진 것으로 보인다. 다만 그것은 쿠버네티스 문서가 정한 동작이지 이 실험이 확인한 것이 아니다. 엔드포인트 목록은 읽지 않았고, 파드는 지연을 풀자 재시작 없이 바로 돌아왔다.

예측 하나가 빗나갔다

주입 전에 적어 둔 예측 가운데 낙관적 락 충돌은 나오지 않았다. 계획서에 적힌 줄은 이랬다.

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

지연을 거는 동안 관련 로그는 0 줄이었다.

낙관적 락은 행을 잠그지 않고 읽은 뒤 갱신할 때 버전 값이 그대로인지 확인하는 방식이라, 같은 행을 여러 요청이 고칠 때 충돌이 난다. 그런데 로그인은 세션 행을 INSERT 하지 UPDATE 하지 않는다. 같은 행을 고치는 요청이 없으므로 확인할 버전도 충돌할 대상도 없다. 예측이 빗나간 이유는 락 구현이 아니라 연산의 종류에 있었다. 충돌이 0 건이라는 결과가 남은 것은 예측을 먼저 적어 두었기 때문이다.

이번에 재지 않은 것

지연을 200 밀리초 한 점에서만 걸었다. 50 밀리초나 500 밀리초에서 응답이 어떻게 되는지, 넣은 값이 왕복 횟수만큼 더해지는 것이 다른 값에서도 그대로인지는 재지 않았다.

어느 지연부터 readiness 가 실패하는지도 재지 않았다. 200 밀리초에서 실패한 것은 봤지만 그 아래 어디가 경계인지 모르므로, 이 기록은 실패하는 값 하나만 대고 실패하기 시작하는 값은 대지 못한다.

프로브가 실패한 뒤 파드가 서비스 엔드포인트에서 실제로 빠졌는지도 재지 않았다. 엔드포인트 목록을 읽는 명령은 원상복구 확인표에 들어 있지만, 부하 중에도 회복 뒤에도 그 출력이 남지 않았다.

동시 요청 수도 20 건 한 점이다. 커넥션 풀에서 최대로 쓴 커넥션이 19 개였으니 풀 상한 근처였을 수 있는데, 풀 크기를 바꿔 가며 22.2 초가 어떻게 움직이는지는 확인하지 않았다.