JFR로 잡은 12분 Jenkins 배치 Hang의 진실
무신사 MWMS의 Spring Batch에서 발생한 Jenkins 배치 Hang 현상으로 작업자에게 보낼 피킹 지시서 분해 작업에 병목 발생
기존 개선에도 불구하고 사라지지 않던 평균 5분, 최악 12분간의 JVM 멈춤 현상을 해결하기 위해 JFR 도입 결정
JFR 분석 결과, 가장 의심했던 AwsLogsAppender가 아닌 Aurora RO replica의 N+1 쿼리가 진짜 원인임을 밝혀냄
N+1 쿼리 최적화를 통해 쿼리 수를 1/8로 줄이고 Aurora 부하를 경감시켜 hang 현상 해결 및 안정성 확보
JFR 도입: 운영 코드 변경 없이 진단하는 방법
본문에서는 운영 코드 변경 없이(Zero Code Change) JVM 내부의 복잡한 문제를 진단하기 위해 Java Flight Recorder(JFR)를 도입한 과정을 상세히 설명합니다. JFR은 OpenJDK에 내장된 저오버헤드 프로파일러(Low-Overhead Profiler)로, JVM 이벤트(스레드 상태, I/O, GC 등)를 기록하여 시간 축 기반의 분석을 가능하게 합니다. Thread Dump나 Heap Dump와 달리, JFR은 항상 켜둘 수 있는(Always-on) 특성과 종료 시 자동 덤프(Dump on Exit) 기능으로 재현 어려운 hang 현상 진단에 특히 유용합니다. JVM 옵션 한 줄로 적용 가능하며, 운영 환경에 미치는 부담이 1~2% 수준으로 낮아 안정적인 운영 환경에서의 진단이 가능합니다.
JFR 분석: 가설을 검증하고 진짜 범인을 찾다
JFR 분석은 Threads, Socket I/O, Method Profiling 패널을 중심으로 진행되었습니다. 초기 가설이었던 AwsLogsAppender의 Credential 탐색 지연 문제는 JFR의 Socket I/O 패널에서 CloudWatch Logs로의 매우 짧은 통신 시간(282ms)을 확인함으로써 기각되었습니다. 대신, main 스레드가 Aurora RO replica로의 read 작업에서 누적 124초 이상을 소비하는 것을 확인했습니다. 이는 N+1 쿼리 패턴이 주요 원인임을 시사하며, JFR은 이 패턴이 발생하는 코드 경로까지 명확히 식별해냈습니다.
N+1 쿼리 문제: Aurora RO 부하의 숨겨진 진실
JFR의 Method Profiling 결과, BatchQueryReader.findItemsInPartition 메서드가 138회 호출되는 것을 확인했습니다. 이는 파티션 단위로 개별 쿼리를 실행하는 전형적인 N+1 쿼리 안티패턴(Anti-pattern)입니다. 평소에는 7ms로 짧았던 쿼리가, 동시성 부하가 높은 운영 환경에서는 1.6초까지 지연되었습니다. 이 지연이 138번 반복되면서 약 2분간의 hang이 발생한 것입니다. JFR은 이처럼 부하 시나리오에서만 드러나는 성능 병목을 정확히 포착했습니다.
해결 및 검증: 쿼리 통합과 JFR 재분석
문제의 근본 원인인 N+1 패턴을 해결하기 위해, 파티션별 개별 쿼리를 하나의 통합 쿼리로 변경하는 코드 수정이 이루어졌습니다. 수정 후 운영 DB 시뮬레이션 결과, 대형 작업의 처리 시간이 기존 6,528ms에서 768ms로 약 8.5배 단축되었습니다. 배포 후 JFR을 다시 사용하여 분석한 결과, Socket read 횟수가 138회에서 32회로 감소하고 hang 현상이 사라진 것을 확인했습니다. 이는 JFR이 문제 해결의 전 과정을 추적하고 검증하는 데 핵심적인 역할을 했음을 보여줍니다.
JFR 활용의 가치와 AI 시대의 디버깅
본 사례는 운영 코드 변경 없이(Zero Code Change) 문제를 진단하는 JFR의 가치를 강조합니다. 이는 AI 협업 시 빠른 가설 검증 사이클을 가능하게 하며, 잊혀지거나 사용되지 않던 도구(Underutilized Tools)를 재발견하는 데 도움을 줍니다. AI가 도구를 제안하면, 개발자는 운영 환경에 맞춰 이를 검증하고 적용하는 역할을 수행합니다. JFR과 같이 가벼운 도구(Lightweight Tools)는 AI 시대의 디버깅에서 더욱 중요해질 것입니다.
