무신사 물류기술실 WMS팀이 Jenkins에서 Spring Batch 배치 작업 실행 시 5~12분간 hang이 발생하는 문제를 Java Flight Recorder(JFR)로 추적한 디버깅 사례다. 콘솔 로그 상 'Creating AWSLogs Client' 직후 침묵이 이어져 AwsLogsAppender가 범인으로 의심됐지만, JFR 분석 결과 실제 원인은 Aurora DB에 대한 N+1 쿼리 138회 반복이었다. 통합 쿼리로 개선 후 단건 평균 처리 시간이 41.2초에서 30초 수준으로 줄었고 hang은 완전히 사라졌다.
핵심 포인트- Jenkins Spring Batch 실행 시 특정 시점에서 5~12분 hang 발생, Reader/Writer 분리로 526.7초 → 41.2초 개선 후에도 hang 지속됨
- 초기 가설: 콘솔 로그 패턴 기반으로 AwsLogsAppender의 AWS 메타데이터 조회를 범인으로 지목
- JFR 도입 — Jenkins Execute Shell에 JVM 옵션 한 줄 추가만으로 운영 환경 진단, 코드 변경 0
- JFR Socket I/O 분석: AwsLogsAppender는 0.28초(별도 워커 스레드), Aurora RO Replica가 136회 read · 124.62초로 main 스레드를 점령
- Method Profiling으로 BatchQueryReader.findItemsInPartition 138회 반복 호출 확인 — 전형적인 N+1 패턴
- 파티션별 개별 쿼리 138회 → 그룹 통합 쿼리 30~40회로 재작성해 hang 해소, Aurora RO Replica 부하 1/8로 감소
상세 정리- 문제 배경: WMS 배치 작업이 새벽 Jenkins 실행 시 5~12분간 hang, Stage 1에서 Reader/Writer 분리로 12.8배 개선(526.7초 → 41.2초)했으나 hang은 잔존했다.
- 초기 가설 수립: 콘솔에 'Creating AWSLogs Client' 로그 직후 침묵이 시작됨 → AwsLogsAppender가 AWS 인스턴스 메타데이터를 HTTP로 조회하며 블로킹한다고 팀 전체가 추정했다.
- 도구 선택 기준: 새벽 배치라 사람이 hang 시점에 대기할 수 없고, 시계열 추적이 필요하며, 운영 코드 변경 없이 적용 가능해야 했다. Thread Dump(시간 축 없음), APM(라이브러리 내부 미관측), Application Logging(배포 필요) 모두 조건 미충족.
- JFR 적용: `-XX:StartFlightRecording=name=batch,settings=profile,dumponexit=true,filename=/tmp/${JFR_NAME}` 한 줄 추가. 오버헤드 1~2%로 운영 환경 상시 가동 가능.
- Socket I/O 분석 결과: CloudWatch Logs(AwsLogsAppender) 12회 · 0.28초는 별도 워커 스레드에서만 동작해 main 스레드 hang과 완전히 무관함 확인 — 가설 기각.
- 진짜 병목 발견: Aurora RO Replica 136회 read · 누적 124.62초가 main 스레드를 잡고 있었다. Method Profiling에서 BatchQueryReader.findItemsInPartition이 138회 반복 호출되는 N+1 패턴 확인.
- 개선 방법: 파티션별 개별 쿼리 138회를 그룹 단위 통합 쿼리 30~40회로 재작성. 추가 아키텍처 변경 없이 쿼리 구조만 수정.
- 성능 결과: 단건 평균 41.2초 → 30초, 단건 최악 113초 → 60~90초 수준으로 개선, Aurora RO Replica 부하 1/8로 감소, hang 완전히 해소.
- 핵심 교훈: 로그 패턴으로 추론한 '가장 그럴듯한 가설'이 가장 위험했다. JFR의 시간 축 Socket I/O + Method Profiling 데이터가 추론 없이 근본 원인을 드러냈다.
왜 읽나JVM 기반 배치 작업의 hang이나 성능 문제를 코드 변경 없이 JFR로 진단하는 실전 워크플로우가 필요한 백엔드 엔지니어에게 유용한 레퍼런스.
무신사 테크·
여기어때 (GC컴퍼니)·
LINE Engineering·