비동기 로깅 배포 후기 (최종)
- 무엇을 고쳤나
- 왜 스레드가 아니라 큐였나
- synchronized 지연은 사실상 사라졌다
- 예측은 94%, 실제는 48%
- 가장 느린 API가 3배 가까이 늘었는데도 빨라졌다
- 측정의 한계
- 회고
이전 글 #1, #2의 후속글입니다. 이전 글을 읽지 않으셔도 따라오실 수 있도록 작성했습니다.
API 요청들이 한데 묶여 지연되던 현상을 비동기로 개선했습니다.
- synchronized 경합 구간의 500ms 초과 지연이 거의 사라졌습니다. (1.83% → 0.006%)
- P95는 94% 개선될 것으로 예상했으나, 48%에 그쳤습니다. (1,079 → 562ms)
- 특정 API를 제외하면 개선치가 더욱 상승합니다. (P95 69% 개선, P99 87% 개선)
(~P20 구간은 절댓값이 7~20ms로 작아, 큐에 넣는 비용이 개선치를 상쇄합니다.)
1. 무엇을 고쳤나
API 요청들이 하나의 락에서 줄을 서는 현상이 있었습니다.
// 기존: 모든 요청이 같은 락에서 경쟁
synchronized(q) {
while (!q.isEmpty()) {
dao.insertLog(q.poll()); // 실제로는 9개 쿼리
}
}
이를 hazelcast라는 인메모리 DB로 개선했습니다.
// 개선: 큐에 넣고 즉시 반환. 저장은 배치가 담당
hazelcastQueue.offer(dto);
요청이 동시다발적으로 일어날수록, 아니면 요청 자체가 느릴수록 더 많은 요청들이 한데 묶이고, 그래서 훨씬 더 느려집니다. 원리는 이전 글의 두 번째 주석에 있습니다.
2. 왜 스레드가 아니라 큐였나
이유는 세 가지입니다.
-
insertLog는 9개 쿼리입니다. 응답 트랜잭션에 함께 두기엔 부담스럽습니다. -
Spring Batch가 있었습니다. 기록 부하를 분담할 수 있습니다.
-
실패가 더 명시적입니다. 스레드는 jvm/pod가 죽으면 사라집니다. 인메모리 DB는 백업 복제본이 있고, 가득 차면 exception을 남길 수 있습니다.
설계와 구현 상세는 이전 글의 “설계 및 구현”에 있습니다.
3. synchronized 지연은 사실상 사라졌다
배포 전 30일(3.1~3.30) 174만 건, 배포 후 29일(4.1~4.30) 192만 건을 비교했습니다.
500ms 초과 비율이 1.83%에서 0.006%로 떨어졌습니다. synchronized 지연은 사실상 사라졌습니다.
| 지표 | 배포 전 | 배포 후 | |
|---|---|---|---|
| 500ms 초과 비율 | 1.83% | 0.006% | ▼99.7% |
다만 이 지표는 간접 지표입니다. 즉, 모든 synchronized 지연을 식별한 것이 아닙니다. 또, 특정 API를 제외한 수치입니다. 이렇게 “추정”된 이유는 #6에서 후술합니다.
4. 예측은 94%, 실제는 48%
이전 글에서 저는 작은 실험을 세워 P95 94% 개선을 예측했습니다.
@Around((... insertLog(..))) // 로그를 추가할 때에는
public Object ... {
if (ThreadLocalRandom.current().nextInt(100) < 3) { // 3% 확률로
try {
Thread.sleep(5000); // 5초 지연
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
}
}
실제 배포 후 개선치는 48%였습니다. 이유는 두 개입니다.
이유 1. 실험이 실제를 면밀히 모사하지 못했습니다
실험은 휴리스틱으로 “3% 확률로 5초 고정 지연”을 가정했습니다. 실제는 그렇지 않았습니다.
운영의 지연은 고정된 5초가 아니라, 수백 ms에서 수 초까지 넓게 퍼져 있었습니다. 5초라는 단일 값을 가정한 모델은, 이 분포의 개선폭을 실제보다 크게 추정합니다.
실험 설계는 이전 글의 “실험 설계”에 있습니다.
이유 2. 전체 통계가 하나의 API에 크게 영향받고 있었습니다
일전에 분석했듯, API의 악화 원인은 두 개였습니다.
| API / 원인 | synchronized 때문 | 페이지네이션 쿼리 때문 |
|---|---|---|
| 세부사업별 세출현황 API | ✅ | ✅ |
| 나머지 API | ✅ | ❌ |
이번 배포는 synchronized 지연만 없앴습니다. 페이지네이션 쿼리 지연은 그대로 남습니다. 이 API(세부사업별 세출현황)의 느린 응답이 전체 P95를 악화시킵니다.
그래서 그 API를 빼고 다시 봤습니다.
| 지표 | 전체 API | 나머지 API | ||
|---|---|---|---|---|
| 평균 | 167.9 → 122.2ms | ▼27% | 76.6 → 27.5ms | ▼64% |
| 중앙값 | 56 → 34ms | ▼39% | 41 → 23ms | ▼44% |
| P95 | 1,079 → 562ms | ▼48% | 170 → 53ms | ▼69% |
| P99 | 2,322 → 1,936ms | ▼17% | 997 → 134ms | ▼87% |
이 API를 빼면 P95는 69%, P99는 87%까지 회복됩니다.
5. 가장 느린 API가 3배 가까이 늘었는데도 빨라졌다
“다른 API들이 거의 쓰이지 않아서 하나의 API가 전체 통계에 영향을 주는 것 아니냐”는 의문이 들 수 있습니다.
그건 아닙니다. 다른 API도 많이 호출됩니다.
| 엔드포인트 | 3월 호출량 | 4월 호출량 |
|---|---|---|
| WCEGCF | 922,383 | 435,147 |
| HCFDA | 398,629 | 424,408 |
| QWGJK (세부사업별 세출현황) | 330,917 | 910,213 |
| 그 외 | 90,420 | 154,473 |
| 합계 | 1,742,349 | 1,924,241 |
심지어 가장 느린 이 API는, 배포 후 호출량이 약 2.75배로 늘었습니다. 그럼에도 개선됐습니다.
| 지표 | 전체 API | 나머지 API | 세부사업별 세출현황 API | |||
|---|---|---|---|---|---|---|
| 평균 | 167.9 → 122.2ms | ▼27% | 76.6 → 27.5ms | ▼64% | 557.4 → 227.6ms | ▼59% |
| 중앙값 | 56 → 34ms | ▼39% | 41 → 23ms | ▼44% | 173 → 70ms | ▼60% |
| P95 | 1,079 → 562ms | ▼48% | 170 → 53ms | ▼69% | 2,317 → 1,647ms | ▼29% |
| P99 | 2,322 → 1,936ms | ▼17% | 997 → 134ms | ▼87% | 2,672 → 2,082ms | ▼22% |
평균과 중앙값은 확실히 좋아졌습니다. P95 이상만 쿼리 때문에 소폭 개선됐습니다.
6. 측정의 한계
synchronized 지연은 전수조사가 어렵다
이상적인 검증 방식은, synchronized 지연 트랜잭션을 모두 알아내 개수를 비교하는 것입니다. 그러나 그럴 수가 없었습니다. 이유는 세 가지입니다.
- APM(제니퍼5)에서는 트랜잭션별 쿼리 기록을 일괄로 조회할 수 없습니다.
- CSV로 내려받아도 쿼리 실행 정보는 빠져 있습니다.
- JDBC 직접 접근은 기술지원팀이 허가하지 않았습니다.
다행히 나머지 API는 응답시간이 대부분 300ms 안팎입니다. 나머지 API에서 500ms를 넘으면 아주 높은 확률로 synchronized 지연입니다.
제게 필요한 건 “synchronized 지연이 유의미하게 사라졌는가”입니다. “synchronized 지연의 전체 개수”를 알 필요는 없습니다. 때문에 나머지 API에서의 500ms+ 수를 비교하게 된 것입니다.
다행히 1.83% → 0.006%는 강력한 수치였기 때문에, 검증의 핵심 지표로 차용하게 되었습니다.
데이터가 깨끗하지 않다
4/3은 시스템 문제로 APM에서 로그가 누락됐습니다. 4/17에는 1분간 장애가 있어 한 API에서 2만~5만ms짜리 응답이 16건 나왔습니다. 이 값들은 손수 확인해 잘라냈습니다.
통제된 실험이 아니다
이번 검증은 단순히 배포 전후를 관찰해 비교했을 뿐입니다. 측정 구간 안에 다른 배포도 있었으므로, 엄밀하게 같은 환경이라 볼 수 없습니다. 또, 위에서 표로 적었듯 API별 총 호출량도 서로 다릅니다.
7. 회고
-
모종의 이유로 로깅이 유실될까봐 전전긍긍했습니다. 배치의 최소 실행 주기는 10분이었거든요. 그래서 consuming 단계를 별도로 로깅했습니다. 약 34일간 처리 118.5만 건 중 실패 0건, 3,300여회 모든 스케줄 실행에서 큐 미소진(드레인 실패) 0회였습니다. 최대 적체량도 큐 용량(100,000건)의 20.4%에 그쳐, 가장 혼잡한 순간에도 약 80% 버퍼가 남아 있었습니다. 실행 1회 소요는 평균 4.3초, 최악 약 3.6분이었습니다.
-
트랜잭션을 일일이 눌러봐야 알 수 있는 결함을 식별하고, 솎아낼 가설을 세우고 검증하는 과정이 재밌었습니다.
-
APM의 부족한 기능에도 불구하고, csv와 python을 활용해 통계를 내고 데이터를 확인하는 과정도 재밌었습니다.
-
fallback 처리를 고민하거나, backpressure를 계산하는 등 데이터 유실을 고민해 본 과정이 좋은 교훈으로 남았습니다.
-
세부사업별 세출현황 API의 페이지네이션 쿼리 문제는 후속 과제입니다. 이 API의 P95는 여전히 1,647ms입니다. 인덱스를 다시 구성하거나, 페이지네이션을 keyset 방식으로 바꾸고자 합니다.
긴 글 읽어주셔서 감사합니다.