JEUS Bug에 의한 OutOfMemoryError 현상 - WAS Troubleshooting 사례(3)

JEUS 인스턴스 6대를 클러스터링한 업무 시스템에서 원인 불명의 OutOfMemoryError 와 Hang-up 이 간헐적으로 발생한 사건을, 남은 로그만으로 추적한 기록이다. Thread dump 와 GC log 를 교차 분석해 JEUS 내부 모듈이 1.9GB 짜리 byte 배열을 요청한 것을 찾아냈고, Tmax 가 자사 버그로 인정해 패치로 해결됐다.

핵심 포인트

OOME 발생 시점 Javacore 의 MEMINFO 를 보면 전체 Heap 2GB 중 사용은 약 470MB, free 가 약 1.5GB 였다. 여유가 있는데 OOME 가 났다는 모순이 출발점이다.
OOME 이전 3일치 GC log 에 지속적인 메모리 증가가 없어 누수가 아니라 순간적인 대용량 할당 실패로 방향을 잡았다.
GC log 의 allocation-unsatisfied 태그에 찍힌 bytesRequested 가 2,013,331,464 byte, 약 1.9GB 였고 같은 줄의 threadId 가 추적 키가 됐다.
그 threadId 로 Thread dump 를 뒤지니 요청 자료형은 bytecode 표기 B, 즉 byte 배열이었고 stacktrace 의 주체는 JEUS 내부 모듈의 LoginInformation.readLoginInformation() 144라인이었다.
Tmax 회신은 Session Manager 중복 로그인 기능에서 수신측이 byte array 를 정상 deserialize 하지 못하면 비정상적으로 큰 배열을 new 요청한다는 것. 패치 적용 후 문제가 사라졌다.

상세 정리

장애는 발생 시점과 패턴에 규칙성이 없어 재현을 기다릴 수 없었고, 남아있는 로그만으로 root cause 를 밝혀야 하는 조건이었다.
1단계는 Thread dump. Javacore 의 Dump Event 가 systhrow 로 OutOfMemoryError 를 가리키는지 먼저 확인해 이 덤프가 OOME 시점의 것임을 확정한다.
2단계는 GC log. 누수인지 순간적 대용량 요청인지 가르는 게 목적이고, 3일치에 증가 추세가 없어 누수 가설을 버렸다.
3단계는 교차 분석. GC log 에서 얻은 threadId 로 Thread dump 를 찾아 요청 객체의 class id 와 메모리 주소, 최종적으로 NULL 을 리턴받아 할당에 실패한 사실을 확인한다.
판단 근거: scope 값은 page, request, session, application 정도라 20 byte 면 충분한데, 이 값을 담는 클래스가 1.9GB 를 요청하는 것은 비이성적이라고 봤다.
확증 절차: 문제 모듈 LoginInformation.java 를 역컴파일해 144라인이 scope 표현용 byte 메모리를 요청하는 코드임을 눈으로 확인한 뒤 벤더에 이슈를 제기했다.
결과적으로 제공받은 패치를 적용해 해결됐다. 운영팀은 오픈 후 수개월간 자신들의 잘못이 아닌 원인 불명 장애를 떠안고 있었다.

왜 읽나Heap 에 여유가 있는데 OOME 가 나는 상황을 만난 Java, WAS 운영자에게 Thread dump 와 GC log 교차 분석부터 역컴파일까지 가는 추적 절차를 보여주는 사례.

SK C&C 블로그

원문은 여기서 이어서 읽을 수 있어요

원문 읽기

읽음 (0)

·takedown 요청