..


비동기 로깅 배포 후기 (최종)

  1. 요약
  2. 무엇을 해결했나요?
  3. 개선율이 너무 미미한 거 아니에요?
  4. synchronized 지연을 “추정”한 이유는 뭔가요?
  5. 성과

이전 글 #1, #2의 내용을 포함하도록 작성했습니다. 이전 글을 읽지 않으셔도 괜찮습니다.

1. 요약

K8s 환경에서 synchonized를 사용하는 잘못된 API 로깅을 개선했습니다. 배포 전 30일(3.1~3.30) 174만 건, 배포 후 30일(4.1~4.30) 192만 건의 트랜잭션을 비교했습니다.

  • 개선율 = (3월 백분위수 - 4월 백분위수) * 100
  • 초기 개선율이 낮은 이유:
    • 크기가 작아서(7~20ms 수준)
    • Queue.offer() 오버헤드가 발생해서


지표 2일치 (이전 글)   30일치  
P95 2,072 → 1,753ms ▼15% 1,079 → 562ms ▼48%
P99 2,530 → 1,921ms ▼24% 2,322 → 1,936ms ▼17%
  • P95까지는 개선폭이 크지만, P99에서는 크지 않습니다.
  • 특정 API(세부사업별 세출현황)가 전체 응답시간을 오염시키기 때문입니다.


지표 2일치 (이전 글)   30일치  
500ms+ 비율 - - 1.83% → 0.006% ▼99.7%
  • 비정상 지연은 사실상 사라진 것으로 추정됩니다.
  • 500ms 초과 비율로 추산했습니다. 특정 API(세부사업별 세출현황)은 양상이 달라 제외했습니다.

이번 글은 읽기 쉽도록 Q&A 형식을 차용해 보겠습니다.

2. 무엇을 해결했나요?

연쇄 지연을 일으키는 API 로깅 코드를,

ConcurrentLinkedQueue<LogDto> q = new ConcurrentLinkedQueue<LogDto>();

@Around
public Object ... {
  synchronized(q) { //
    while (!q.isEmpty()) {
      var dto = q.poll();
      dao.insertLog(dto);
    }
  }
}

인메모리 DB로 개선했습니다.

@Around
public Object ... {
  hazelcastQueue.offer(dto);
}


Q. 아무튼 동작한다면, 큰 문제가 없다면 그냥 둬도 되는 거 아닌가요?

  1. API들은 주기적으로 크롤링됩니다. 요청들이 갑자기 늘거나 몰리면 비합리적인 대기가 발생하여 고쳤습니다.

  2. 예측이 어려운 행동 양식을 시스템에 방치해 두면, 나중에 원인 파악이 어려울 것 같아 고쳤습니다.


Q. 왜 스레드 안 쓰고 큐 쓰셨어요?

  1. insertLog는 사실 9개의 쿼리로 이루어져 있습니다. 기록 행위가 많습니다.

  2. Spring Batch를 쓸 수 있습니다. 기록 부하를 분담할 수 있었습니다.

  3. 스레드에서 처리할 경우, JVM이 종료되거나 pod가 재시작될 경우를 추가로 고민해야 합니다.

3. 개선율이 너무 미미한 거 아니에요?

우리 API의 지연은 크게 두 가지 때문입니다.

API / 원인 synchronized 때문 페이지네이션 쿼리 때문
세부사업별 세출현황 API ✅ ✅
나머지 API ✅ ❌

이번 배포는 synchronized로 인한 지연을 제거했으므로, 페이지네이션 쿼리 지연은 그대로 남습니다. 이 지연이 전체 API 응답시간을 오염시키기 때문에 그렇게 보이는 것입니다.


Q. 분리하면요? 나머지 API는 극적으로 개선되나요?

  1. 네, 선형적으로 개선됩니다.
지표 전체 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%
  1. 주요 지표를 보면 더욱 명확합니다.


Q. 다른 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

  1. 아닙니다. 다른 API도 많이 호출됩니다.

  2. 심지어 부하가 강한 세부사업별 세출현황 API는, 배포 후 호출량이 3배로 늘었습니다.


Q. 그럼 그 API에는 개선된 게 거의 없는 거에요?

  1. 세부사업별 세출현황 API도 전체적으로 개선됩니다.

  2. p95+ 구간은 쿼리 떄문에 높은 응답시간을 가지고 있지만, 여전히 배포 후가 더 낫다는 걸 알 수 있습니다.

지표 전체 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%
  1. 주요 지표도 그렇습니다. 평균, 중앙값은 확실히 나아졌습니다. 그러나 p95+ 구간은 소폭 개선되었죠.

4. synchronized 지연을 “추정”한 이유는 뭔가요?

현실적으로 지연 현상을 전수조사 할 수 없기 때문입니다.


Q. 왜 전수조사가 어려워요?

  1. APM(제니퍼5)의 한계 때문입니다. 각 트랜잭션마다 기록이 일어났는지 봐야 하는데, 일일이 눌러보는 수밖에 없습니다.

  2. csv export 기능에도 쿼리 실행 정보는 담기지 않습니다.

  3. APM(제니퍼)의 JDBC 드라이버로 접속하면 찾을 수 있겠지만, 기술지원팀에서 허가하질 않았습니다.


Q. 추정은 얼마나 엄밀한가요?

  1. 대부분의 API는 300ms 안팎의 응답시간을 가지고, 500ms를 넘는 일이 거의 없습니다.

  2. synchronized 지연 현상은 모든 API에 일어나므로, 어느 트랜잭션이든 500ms가 넘어간다면 아주 높은 확률로 synchronized 때문일 것이라고 추측했습니다.

  3. 하지만 세부사업별 세출현황 API는 쿼리 문제로 2,000ms 넘는 경우가 많았습니다. 그래서 이 API만 제외하고 500ms+ 트랜잭션 비율로 추산하게 되었습니다.

성과

  1. 각 요청이 독립적이 되면서, 트래픽 증가가 곧 성능 저하로 이어지는 악순환이 사라졌습니다.