Created at 2026-04-03
Last modified at 2026-04-09

비동기 로깅 배포 후기

요약
돌아보기
왜 응답시간은 극적으로 개선되지 않았나
성과, 그리고 향후 과제

1. 요약

이전 글에서 비동기 로깅을 도입하면 P95에서 94%가 개선될 것이라고 가정했었죠. 배포 전 2일(3/29~3/30)과 배포 후 2일(4/1~4/2) 트랜잭션을 비교해 봤습니다.

묶임 지연 현상은 사실상 제거된 것으로 보입니다. 통상 지연시간을 뛰어넘는 비율을 비교했습니다.

응답시간은 전체적으로 개선되었지만, 극단적인 꼬리 지연은 여전합니다. 이 문제는 특정 API의 인덱싱과 페이지네이션 쿼리 문제로 확인됐습니다.

지표	배포 전	배포 후	개선
최대 응답시간	13,369ms	4,349ms	▼67%
중앙값	82ms	30ms	▼63%
평균	269ms	172ms	▼36%
p95	2,072ms	1,753ms	▼15%
p99	2,530ms	1,921ms	▼24%

2. 돌아보기

저는 API에서 잘못된 로그 코드를 발견해 이를 수정하려 했었습니다. 요청이 모두 synchronized로 묶이는 문제였습니다.

sequenceDiagram
    participant A as 요청 A
    participant B as 요청 B
    participant Q as ConcurrentQueue
    participant DB as DB

    Note over A,B: 두 요청이 거의 동시에 시작

    A->>A: API Querying
    B->>B: API Querying

    A->>Q: 큐에 로그 추가
    A->>Q: Lock 획득
    activate Q

    B->>Q: 큐에 로그 추가
    B->>Q: Lock 대기

    Note over Q,DB: 요청 A가 큐를 비울 때까지<br/>요청 B는 대기

    Q->>DB: A의 로그 저장
    Q->>DB: B의 로그 저장

    Q-->>A: Lock 해제 & 응답 (느림)
    deactivate Q

    B->>Q: Lock 획득 → 큐가 비어있음 → 즉시 해제
    Q-->>B: 응답 (느림)

    Note over A,B: 두 요청이 거의 동시에 종료<br/>(A가 B의 로그까지 처리했기 때문)

만약 4,000ms짜리 요청 세 개가 운 나쁘게 한데 묶인다면, 최대 응답시간이 12,000ms까지 뛰게 되었죠.

(요약 표를 참고하시면, 배포 전 최댓값이 13,369ms임을 확인하실 수 있습니다.)

이 문제를 분석하던 당시, 트랜잭션들을 대량으로 분석할 방법이 없었습니다. 그래서 저는 가설을 세우고 이를 실험했었습니다:

모든 API가 3~5% 확률로 묶일 것이다.

3. 왜 응답시간은 극적으로 개선되지 않았나

실험의 추정이 잘못되었기 때문이었습니다. 저는

(가정) 모든 API가 3~5% 확률로 묶일 것

라고 가정했습니다. 그런데 실제는 이랬습니다:

(실제) 모든 API에서 6% 묶임 발생, 그러나 대부분은 단 하나의 API에서 발생하고 있었음

a. 왜 특정 API만 묶이나

이 API는 세부사업별 세출현황이라는 API입니다.

각 지방자치단체가 어느 사업에 금액을 얼마나 지출했는지

를 매일 업데이트하는, 인기있는 API입니다.

이 API는 전국의 집행 내역을 매일 업데이트하기 때문에, 쿼리의 실행 속도 자체가 느렸습니다.

문제는 느린 요청일수록 묶임 현상이 빈도높게 발생한다는 점입니다. 첫 요청이 오래 걸리면, 다음 요청은 첫 요청을 기다리게 될 가능성이 높습니다.

그래서 상대적으로 헤비한 이 API에 대부분의 묶임 현상이 발생하고 있던 겁니다.

b. 왜 이 API만 느린가

나머지 API들은 원래부터 응답시간이 짧았습니다. 아무리 길어야 300ms를 넘지 않습니다.

세부사업별 세출현황 API도 대부분의 요청들은 300ms 안팎을 유지합니다(p1~p65). 그런데 특정 요청인자를 활용하지 않으면 2,000ms 안팎의 응답속도를 가지게 됩니다(p65~p99).

이 API의 검색인자 중에는 wa_laf_cd가 있습니다. 예컨대 ‘1100000’을 넣으면, ‘서울 본청’만 조회할 수 있는 식입니다.

이 검색인자를 넣지 않을 경우 전국구를 조회하는데, 두 검색결과의 행 수가 당연히 크게 차이납니다. 예컨대 2026-03-01 자료는:

전국구: 438,969행
서울 본청: 4,346행

100배 정도 차이납니다. 문제는:

인덱스가 API 응답에 맞춰 효율적으로 구성되지 않았다는 점¹
API 응답이 모두 정렬과 페이지네이션을 거치기 때문에 선형적으로 비효율적이라는 점²

에 기인합니다.

c. 정리하자면…

응답시간의 악화는 사실 자료수가 많은, 인기있는 API 때문이었고, 그 이유는:

➊ 비효율적인 인덱스

➋ 선형적으로 악화되는 정렬, 페이지네이션

➌ 응답을 모두 묶어 지연시켜 버리는 잘못된 로깅 코드

저는 이 중 ➌번만을 고친 셈입니다.

4. 성과, 그리고 향후 과제

성과

낮은 응답시간의 비율이 높아졌습니다.

인기있는 API ㅡ 세부사업별 세출현황에서도 같은 현상이 보입니다. 그럼에도 2,000ms+ 꼬리 지연은 여전합니다.

비동기 로깅은 한 건의 실패 없이 아직까지 잘 작동합니다.

향후 과제

➊ 인덱스를 더 잘 활용하도록 수정/추가하거나

➋ 페이지네이션을 keyset으로 변경

하는 것입니다. 또, 이미 배포한 결과를

➌ 한 달치 통계량으로 확대해 모니터링 및 평가

하는 것도 포함되겠습니다.

References

이 API는 하나의 테이블을 사용합니다. 테이블에는 인덱스가 두 개 있습니다.
- 1번 인덱스: FYR, EXE_YMD, EXE_END_YMD, WA_LAF_CD, …
- 2번 인덱스: FYR, (미사용 컬럼들), EXE_END_YMD
조회 쿼리는
- 전국구 조회 쿼리: WA_LAF_CD 미포함
- 자치단체별 조회 쿼리: WA_LAF_CD 포함
전국구는 2번 인덱스를, 자치단체별은 1번 인덱스를 활용할 것이라고 기대하셨을 겁니다. 하지만 EXPLAIN 결과는 반대입니다:
```
-- 전국구
INDEX RANGE SCAN (인덱스_01)
    access(FYR, EXE_END_YMD, EXE_YMD)

-- 자치단체별
INDEX RANGE SCAN (인덱스_02)
    access(FYR, EXE_END_YMD)
    table filter(WA_LAF_CD, EXE_YMD)
```
이에 대한 분석 글은 별도로 정리할 예정입니다. ↩
두 쿼리의 실행계획 구조는 동일합니다.
```
INDEX RANGE SCAN
 → TABLE ACCESS
  → SORT ORDER BY STOPKEY
   → COUNT STOPKEY(ROWNUM<=1000)
    → VIEW(RN>0)
```
차이는 정렬 대상의 크기입니다. 전국구 쿼리는 인덱스의 access predicate만으로 결과를 좁히므로 ~400K건 전체를 정렬해야 합니다. 페이지네이션이 깊어질수록 더 많은 행을 skip해야 하므로 선형적으로 악화됩니다. 반면 자치단체별 쿼리는 table filter(WA_LAF_CD) 이후 ~4K건만 남기 때문에 정렬 비용이 훨씬 적습니다. ↩