시간당 34GB의 로그 발생
사내 인프라 담당자가 우리가 담당하고 있는 서버의 로깅 설정 관련된 내용을 공유해주었다. 간단하게 정리하면 다음과 같다:
- Cloudwatch는 로그 GB마다 과금되는 형태
- 불필요한 로그로 인해 비용이 발생하는것으로 확인됨
- 현재 서비스에서 발생하는 로그(특히 info)를 점검할 필요가 있음
도메인 개발자라서 인프라 업무를 직접 수행할 기회와 권한이 없었다. 이번에 인프라팀이 공유해준 걸 계기로 개인적으로 살펴보았다. 먼저 Cloudwatch에 들어가 직접 눈으로 로그 발생량을 확인했다.
우리 서비스는 HR 서비스이기 때문에 대부분의 트래픽은 9시부터 18시 사이에 발생한다. 시간당 대략 34GB(2.7억건)의 로그가 발생하며 그 중에 44% 정도가 jdbc.resultset=INFO 에서 발생함을 확인했다. 여기서 몇 가지 의문이 들었다.
- 쿼리 로그는 디버깅용 아닌가?
- 운영환경에서 쿼리 로그를 켜두는게 맞나?
- 대량의 로그 발생이 서버 성능에 어떻게 영향을 미치는가?
따라서 다음과 같은 측정항목들을 고민했다. 이를 바탕으로 실험 및 분석을 하고 글 마지막에는 실무 운영방식에 대해 정리하여 마무리한다.
- 로그량에 따른 TPS 변화
- 동기/비동기 로깅 방식에 따른 차이
- Text/JSON 포맷 전환에 따른 차이
실험 설계
위에서 언급한 문제는 jdbc.resultset을 끄면 해결되겠지만 로그량, 출력방식, 포맷이 각각 성능에 얼마나 영향을 주는지 분리해서 측정하고 싶었다. 변인을 하나씩 바꾸는 5단계 구조로 설계했다.
전체 소스코드와 설정 파일은 https://github.com/gukin-han/logging-lab 에서 확인할 수 있으며 실험계획은 자세한 실험 계획은 별도의 파일에 문서화해두었다.
5단계 매트릭스
| Phase | Appender | 포맷 | jdbc.resultset | 요청당 로그량 |
| 1 | - (OFF) | - | OFF | 0 줄 |
| 2 | Sync Console | Text (PatternLayout) | ON | ~ 5,500 줄 |
| 3 | Sync Console | JSON (JsonTemplateLayout) | ON | ~ 5,500 줄 |
| 4 | Async (Disruptor) | JSON | ON | ~ 5,500 줄 |
| 5 | Async (Disruptor) | JSON | OFF | 0 줄 |
H2에 더미 데이터 500건을 INSERT하고, GET /api/logs/test로 전체 조회한다. jdbc.resultset이 켜져 있으면 500건 x 컬럼별 getXxx()호출(11회)로 요청당 약 5,500줄의 로그가 발생한다.
row 1개를 읽을 때 발생하는 jdbc.resultset 로그:
ResultSet.next() returned true ← 1줄
ResultSet.getLong(1) returned 1 ← 1줄 (id)
ResultSet.wasNull() returned false ← 1줄
ResultSet.getString(2) returned "User1" ← 1줄 (name)
ResultSet.wasNull() returned false ← 1줄
ResultSet.getString(3) returned "..." ← 1줄 (email)
ResultSet.wasNull() returned false ← 1줄
ResultSet.getString(4) returned "..." ← 1줄 (department)
ResultSet.wasNull() returned false ← 1줄
ResultSet.getString(5) returned "..." ← 1줄 (description)
ResultSet.wasNull() returned false ← 1줄
통제 변인
H2 In-Memory DB를 사용하여 네트워크, 디스크의 I/O 변수를 제거하여 로깅이 성능에 미치는 영향만 측정할 수 있도록 했다.
동일한 API, 데이터, 부하조건(1분동안 VUser 100)을 사용했으며, Spring Profile로 로깅 설정만 전환 (-Dspring.profiles.active=phaseN)하는 방식을 사용했다.
결과
1차 실험 결과 동기/비동기 그리고 json/text 에 따른 차이는 보이지 않았다. 오히려 로그 발생량이 성능 차이에 지배적인 영향을 미쳤다. 결과는 아래 그래프를 통해 확인할 수 있는데 로그 발생량에 따라 TPS의 차이가 커서 로그 스케일로 나타냈다.
Baseline(Phase 1)에 비해 Phase 2는 TPS가 14.6으로 170배 낮음을 확인할 수 있다. 포맷을 Json으로 변경한 Phase 3와 비동기로 전환한 Phase 4도 Phase 2와 큰 차이를 보이지 않았다. 다음 표에 Baseline 대비 TPS차이를 정리해두었다.
| Phase | 설정 요약 | TPS | avg (ms) | p95 (ms) | Baseline 대비 |
| 1 | Baseline (로깅 OFF) | 2,485 | 40.18 | 173.37 | 100% |
| 2 | Sync + Text + jdbc.resultset ON | 14.6 | 6,510 | 7,180 | 0.59% |
| 3 | Sync + JSON + jdbc.resultset ON | 13.5 | 7,000 | 7,600 | 0.54% |
| 4 | Async + JSON + jdbc.resultset ON | 18.3 | 5,240 | 5,720 | 0.74% |
| 5 | Async + JSON + jdbc.resultset OFF | 2,429 | 41.12 | 176.62 | 97.7% |
jdbc.resultset을 OFF 한 Phase 5에서 TPS가 2,429로 Baseline대비 97.7%까지 회복했다. 위 실험 결과를 바탕으로 로그량이 지배적인 요소임을 확인할 수 있었는데, Text를 JSON으로 동기를 비동기로 변환했을때의 차이점을 분명히 확인하기 어려워 추가적인 실험을 진행했다. 지금 Phase 2, 3, 4는 그 값이 너무 낮아서 서로간의 차이를 명확히 확인하기 어려운 점이 한계점이었다.
따라서, 로그량을 의도적으로 줄이면 TPS가 높아지는데, 높아진 TPS는 측정 해상도(Resolution)를 높여 차이점을 확인할 수 있을것으로 예측했다. 아래는 그 실험 결과를 그래프와 표로 나타냈다.
| Phase | 설정 요약 | TPS | avg (ms) | p95 (ms) | Baseline 대비 |
| 1 | Baseline (로깅 OFF) | 2,485 | 40.18 | 173.37 | 100% |
| 2b | Sync + Text + jdbc.sqltiming ON | 1,955 | 51.08 | 209.81 | 78.7% |
| 3b | Sync + JSON + jdbc.sqltiming ON | 1,982 | 50.39 | 204.87 | 79.8% |
| 4b | Async + JSON + jdbc.sqltiming ON | 2,004 | 49.83 | 202.52 | 80.6% |
예측과는 다르게 이 조건에서도 동기/비동기 그리고 JSON/Text간의 차이점이 오차범위 내에 있어 이 실험 조건 하에서는 성능 차이는 결국 로그량이 결정함을 확인할 수 있었다.
왜 느릴까? (VisualVM)
결과적으로 로그량에 의해 TPS가 170배 하락했음을 확인할 수 있었다. 이러한 성능 하락의 근본적인 원인은 무엇일까? JVM 내부에서는 어떤 일이 발생하고 있는것일까?
jdbc.resultset을 ON 하는 경우 적어도 5,500개의 LogEvent 객체가 Eden 영역에 생성된다. 만약 과한 객체 생성으로 Minor GC가 빈번하게 수행되면 성능 하락의 원인이 될 수 있지 않을까? 이를 확인하기 위해 추가적으로 VisualVM을 이용해 GC 활성도와 Heap메모리의 프로파일을 측정했다.
| Phase | GC 활동 | CPU 사용률 | 힙 사용량 |
| 2 (Sync) | 0.1% | ~58% | ~108MB |
| 4 (Async) | 0.0 - 0.3% | 65-75% | ~332MB (변동 있음) |
| 5 (jdbc OFF) | 0.0% | 70-80% | ~62MB |
가장 주목할 점은 GC활동이 예상과 다르게 매우 낮다는 점이다. 따라서, 낮은 성능의 원인은 빈번한 GC가 아님을 확인할 수 있었다.
이와 별개로 몇가지 짚고 넘어갈 부분이 있다. 먼저, Phase 2는 동기적으로 처리되어 힙 사용량이 상대적으로 높지 않았다. 반면에 비동기로 처리된 Phase 4는 힙 사용량이 Phase 2에 비해 3배가 높았는데, 이는 엄청난 로그량이 Ring Buffer 만큼 큐잉되어 유지되는 것으로 추측할 수 있다. 로깅이 완전히 OFF된 Phase 5는 62MB로 가장 낮은 힙 사용량을 보여줬다.
어플리케이션 자체로 62MB 정도가 베이스로 유지되며 동기 로깅에 대한 오버헤드는 약 46MB로 해석할 수 있다. 비동기 실행으로 Ring Buffer의 기본 슬롯 개수인 262,144 (256 * 1024)는 각 객체가 160-170바이트 만큼 차지하기 때문에 초기화할때 약 40MB 만큼의 힙사용량을 필요로 한다. 버퍼에 담기는 모든 객체가 참조하는 다른 객체들은 GC대상이 될 수 없어서 332MB까지 힙사용량이 증가하는 것으로 보인다. 만약 메모리 용량이 부족한 환경이거나 그 만큼의 슬롯이 필요하지 않은 경우는 동기처리 혹은 슬롯의 개수를 줄이는 방법을 고려해볼 수 있다.
병목점이 어딘가? (스레드 덤프)
VisualVM을 통해 GC가 병목점이 아님을 확인할 수 있었지만 명확한 병목점을 특정할 수 없었다. 실제 스레드가 어디서 블로킹되는지 확인하기 위해 jstack으로 스레드 덤프를 수집했다. 자세한 실험 방법은 README 내에 '스레드 덤프 분석' 항목에서 확인할 수 있다.
| Phase 2 (Sync + jdbc ON) | Phase 5 (Async + jdbc OFF) | |
| TPS | 13.3 | 2653 |
| BLOCKED | 7 | 0 |
| RUNNABLE | 15 | 31 |
| WAITING / TIMED_WAITING | 97 | 90 |
Sync에서 발생한 Lock 경합 (Phase 2)
BLOCKED상태의 7개 스레드는 모두 톰캣 워커 스레드(http-nio-exec-*) 임을 확인했다. 흥미롭게도 이 스레드들은 모두 하나의 OutputStreamManager 인스턴스를 대상으로 락 경합이 발생했다.
"http-nio-8081-exec-92" #133 daemon prio=5
java.lang.Thread.State: BLOCKED (on object monitor)
at o.a.l.l.c.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:365)
- waiting to lock <0x00000007ffd6ced8> (a o.a.l.l.c.appender.OutputStreamManager)
at o.a.l.l.c.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:101)
at o.a.l.l.c.layout.PatternLayout.encode(PatternLayout.java:239)
at o.a.l.l.c.appender.AbstractOutputStreamAppender.directEncodeEvent(...)
at o.a.l.l.c.appender.AbstractOutputStreamAppender.tryAppend(...)
...
at net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator.methodReturned(...)
실제 락을 잡고 있는 스레드는 무엇을 하고 있었을까? 해당 스레드는 flushBuffer(), flush() 메서드를 수행하고 있는 것임을 확인할 수 있었다.
- locked <0x00000007ffd6ced8> (a o.a.l.l.c.appender.OutputStreamManager)
at o.a.l.l.c.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:296)
- locked <0x00000007ffd6ced8> (a o.a.l.l.c.appender.OutputStreamManager)
at o.a.l.l.c.appender.OutputStreamManager.flush(OutputStreamManager.java:307)
호출 관계를 정리하면 다음과 같다.
Tomcat 워커 스레드
→ log4jdbc (Slf4jSpyLogDelegator.methodReturned)
→ SLF4J → Log4j2 Logger.log()
→ AppenderControl.callAppender()
→ AbstractOutputStreamAppender.tryAppend()
→ OutputStreamManager.writeBytes() ← 🔒 lock 경합 지점 1
→ OutputStreamManager.flush() ← 🔒 lock 경합 지점 2
→ System.out (stdout fd=1)
이를 통해 하나의 스레드로 하나의 출력만 처리하는 기본 OutputStream의 설계적 한계를 나타낸다.
이와 다르게, Phase 5는 로깅처리를 하지 않기 때문에 BLOCKED 되는 스레드 또한 없었다. 따라서 톰캣 스레드의 대부분이 RUNNABLE상태로 요청처리에 집중하고 있음을 확인할 수 있었다.
Async에서 락 경합은 어떠한가? (Phase 4)
Phase 4의 스레드 덤프는 확인하지 않았지만 흥미로운 사실을 확인할 수 있어서 데이터 흐름 그림을 첨부하였다.
동기 처리에서는 각각의 스레드가 OutputStreamManager의 락 획득을 시도하다보니 경쟁 상태가 발생했다. 반면에 Async는 로깅 처리를 위한 스레드가 1개가 기본으로 설정된다. 즉, 로깅 처리를 위한 스레드는 1개이기 때문에 OutputStreamManager에서 락 경합이 발생하지 않는다.
하지만, 앞에서 처리 속도가 느려 LogEvent 객체를 보관할 Ring Buffer가 꽉차는 문제가 발생하게 된다. 병목 지점이 결국 이 버퍼에 담기 위해 톰캣 워커 스레드들이 대기하는 현상이 발생했다. 부하 테스트 자체가 VUser 수를 100으로 1분간 유지하는 방식이기 때문에 여기서 다른 이슈가 발생하지 않았다. VUser를 100으로만 유지하면 되기 때문에 응답이 올때까지 그저 대기만 하는 상태가 된다. 만약 RPS를 상수로 하여 실험을 했다면 톰캣 워커 스레드풀의 200개를 넘어서는 문제가 발생해서 요청이 유실될 가능성이 있었을 것이다.
한계점
부하 생성기(K6)와 어플리케이션(Spring Boot)가 같은 호스트 머신에서 실행되었다. k6와 Spring Boot가 8코어를 공유하므로 TPS 절대 수치는 분리 환경보다 낮게 나왔을 수 있다. 다만 모든 Phase에서 동일 조건으로 실험하여 Phase간 상대 비교는 유효하다고 생각한다.
스레드 수준의 리소스 배분을 고려하지 못했다. 톰캣 스레드 풀 크기, 비동기 소비자 스레드 수, 코어 대비 스레드 배분에 따른 영향이 분명 존재할것으로 예상하지만 여기서 다루지 않았다. 특히 Phase 4에서 OutputStreamManager를 위한 비동기 처리 스레드가 1개였는데, 스레드 개수에 따른 차이점을 확인하지 못했다.
결론 및 실무 운영 방식
이 실험을 통해서 증명할 수 있는 것은 다음과 같다:
- 로그량이 성능을 지배했다. 동기/비동기, Text/JSON의 차이점보다 로깅이 얼마나 발생하는지가 TPS에 큰 영향을 줬다. 따라서, 실무에서 가장 먼저 할 일은 불필요한 로그를 찍지 않는 것이다.
- jdbc.resultset 같은 로거는 운영 환경에서 반드시 OFF. 요청당 5,500 줄은 실험 설계상 과한 설정이지만 실무에서도 이런 설정이 켜진 채 배포되는 상황이 실제로 발생했다. (Cloudwatch 비용 증가) 환경별 로그 분리가 필요하다.
- 동기 로깅의 병목은 OutputStreamManager의 sychronized 블록이다. System.out이 아닌 Log4j2 내부에서 먼저 락이 걸림을 스레드 덤프로 확인할 수 있었다.
- Async 전환도 새로운 병목점이 생긴다. 로그량이 극적으로 많다면 Ring Buffer가 포화되어 결국 톰캣 워커 스레드가 블로킹 된다. 필요에 따라 Ring Buffer, 소비자 스레드 수 등의 튜닝이 필요하다.
참고 자료
- Async Log4j2, memory leak? | F. Dorado (2019)
- Imax RingBuffer with log4j takes up a lot of memory | Stack Overflow (2020)
- AWS Cloudwatch pricing | AWS
- Understanding the LMAX Disruptor | Tevia Harsanyi (2019)
- Disruptor: High performance alternative to bounded queues for exchanging data between concurrent threads | M Thompson et al. (2011)
