..
비동기 로깅 배포 효과 검증 — 1일차
1. 요약
이전 글에서 비동기 로깅으로 P95 94% 개선을 실험했다. 2026년 3월 31일 운영 배포 후, 배포 전(3/30)과 배포 후(4/1) 24시간 트랜잭션을 비교했다.
운영 배포 1일 기준, cascade 지연은 97% 감소했고, 전체 응답속도는 21~47% 개선되었다.
QWGJK 제외 API
| 지표 | 3/30 | 4/1 | 개선 |
|---|---|---|---|
| mean | 59.9ms | 36.9ms | ▼38% |
| median | 45ms | 24ms | ▼47% |
| p95 | 147ms | 125ms | ▼15% |
| p99 | 203ms | 158ms | ▼22% |
| slow_ratio_500ms+ | 0% | 0% | — |
QWGJK API
| 지표 | 3/30 | 4/1 | 개선 |
|---|---|---|---|
| mean | 336.6ms | 248.9ms | ▼26% |
| median | 163ms | 129ms | ▼21% |
| p95 | 1,801ms | 1,656ms | ▼8% |
| p99 | 2,140ms | 1,847ms | ▼14% |
| slow_ratio_2000ms | 2.91% | 0.09% | ▼97% |
2. 가설 #1. cascade 지연 제거
실험에서 예측한 메커니즘이 운영에서 확인되었다.
cascade 구조 자체가 제거되었다
offer()의 타임아웃은 50ms다. 한 트랜잭션이 다른 트랜잭션의 로깅을 떠안는 구조 자체가 사라졌다.
이전 글에서 포착한 실제 cascade 예시:
- 트랜잭션 #2: API SQL 8개 + 로깅 54개 = 5,210ms
- 트랜잭션 #3: API SQL 8개만 실행했으나 synchronized 대기 = 5,190ms
- 트랜잭션 #4: API SQL 8개만 실행했으나 synchronized 대기 = 2,750ms
배포 후 제니퍼에서 이 패턴은 나타나지 않는다.
slow_ratio의 계단 패턴
- 500~2000ms 구간: 쿼리 고유 지연(인덱싱). 소폭 개선(23~24%).
- 2000ms 초과 구간: cascade가 얹어준 지연. 사실상 소멸(▼97%).
비동기 로깅이 제거한 것은 쿼리 자체의 지연이 아니라, cascade가 얹어준 지연이다.
실험의 P95 94%가 운영에서 재현되지 않은 이유
실험 환경은 이봉 분포(bimodal)였다. 대부분 ~200ms, cascade만 ~5000ms. P95가 cascade 구간 안에 위치했으므로, cascade 제거 = P95 이동 = 94% 개선.
운영 QWGJK는 세 층이다: 빠른 요청 / 쿼리 고유 지연(500~2000ms) / cascade(2000ms+). P95는 중간 층에 걸린다. cascade를 제거해도 P95는 같은 층에 남는다 → P95 8% 개선.
실험과 운영의 병목 구성이 달랐다. 실험이 과대평가한 것이 아니다.
| 실험 P95 | 운영 P95 (QWGJK) | 운영 cascade (2000ms+) | |
|---|---|---|---|
| 배포 전 | 3,983ms | 1,801ms | 2.91% |
| 배포 후 | 231ms | 1,656ms | 0.09% |
| 개선율 | 94% | 8% | 97% |
남은 과제
QWGJK의 500~2000ms 구간은 인덱싱 최적화로 추가 개선 가능하다. 1주, 1달 데이터로 재검증할 예정이다.