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

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

OO 업무시스템은 총 6대의 JEUS instance를 clustering 구성해 운영중인데, 간헐적으로 원인을 알 수 없는 OutOfMemoryError가 발생하며 JEUS Instance가 Hang-up이 걸린다고 한다.

문제 발생시점이나 패턴에서는 어떠한 규칙성도 찾을 수가 없는 상황에서, Hang-up이 발생할 때까지 마냥 기다릴 수는 없는 노릇이다.
그렇다면 남아있는 관련 로그만을 통해 Root Cause를 밝혀내고 개선할 수 있을까?

차근차근 알아보도록 하자…

원인 파악을 위한 첫걸음 - Thread dump 분석

앞선 포스트에서 언급했듯이 Java 쓰레드 덤프는 모든 JVM 관련 issue를 파악하기 위한 기본이 된다.
이번에도 역시 문제발생 시점의 Thread dump를 가장 먼저 분석해 보도록 하자.

아래는 AIX Javacore 파일에서 OutOfMemoryError 발생 시점과 발생할 당시의 Heap Memory 상태를 나타내는 부분을 발췌한 것이다.

위 로그를 보면 Javacore가 생성된 이벤트가 “Dump Event systhrow (00040000) Detail java/lang/OutOfMemoryError”라고 나오는 걸 보아 해당 dump가 OOME가 발생할 때 생성된 것임을 확인할 수 있다.

또한 dump 생성 시점의 Heap Memory 상태를 보여 주는 MEMINFO 부분을 보면 설정된 전체 Heap 2GB 중에 실제로 사용중인 메모리는 약 470MB 뿐이고 나머지 약 1.5GB가 Free Memory인 것을 알 수 있다.

전체 Heap Memory(2GB)의 약 75%(1.5GB)가 Free Memory로 남아 있는 상황에서 OutOfMemoryError가 발생한다?

뭔가 이상하다… 앞 뒤가 맞지 않는다…

Memory 사용 추이 분석 - GC Log 분석

Heap 덤프와 GC log는 JVM의 모든 Memory 관련 issue를 파악하기 위한 기본이 된다.

앞 서 Thread dump를 분석하였으니 이번에는 OutOfMemoryError가 지속적인 메모리 누수에 의한 것인지, 아니면 일시적인 대용량 메모리 요청에 의한 것인지를 판단하기 위해 GC Log를 분석해 보자.

OutOfMemoryError가 발생하기 前 약 3일간의 메모리 사용추이를 검토한 결과, 지속적인 Memory Leak 등의 현상은 보이지 않았다.
(그도 그럴것이 OOME 발생 당시에도 1.5GB의 여유 공간이 남아 있었지 않은가…)
즉, 이번 OOME는 Application에서 특정 트랜잭션을 처리할 때 순간적으로 1.5GB 이상의 대용량 메모리를 요청하여 memory allocation failed가 발생한 것으로 유추할 수 있다.

도데체 어떤 업무를 처리하는데 한꺼번에 1.5GB가 넘는 메모리가 필요하단 말인가…
Application의 업무 처리 로직이 잘 못 된 것인가…?

GC Log의 추가적인 분석을 통해 대용량 메모리 할당을 요청한 트랜잭션을 추적해 보도록 한다.

GC Log의 아래 부분을 해석해 보자.

일단 태그 시작이 allocation-unsatisfied 이다. 메모리 할당에 실패했다는 뜻이다.
그 뒤로 threadId가 나온다. 이 Id로 Thread dump에서 해당 트랜잭션을 찾을 수 있으리라…
연이어 bytesRequested가 나오는데 2,013,331,464 byte… 즉 1024*1024 byte가 1GB이니 무려 약 1.9GB이다.

이 넘이 범인(?)임에 틀림없으렸다!!

Thread dump와 GC Log의 교차 분석

이번에는 위 GC Log에서 발견한 threadId로 Thread dump에서 더 많은 정보를 얻어보도록 하자.

Thread dump의 아래 부분을 분석해 보자.

threadId로 추적된 마지막 라인을 보면, 1.9GB의 메모리를 요청한 object class는 “0x0000000030028500” 이며 memory space id(주소)는 “0x0000010010734B30” 이나 최종적으로 NULL을 리턴받았다는 것을 알 수 있다.(즉 memory를 할당받지 못함)

또한 object class id를 추적해 보면 대용량 메모리를 요청한 object는 아래와 같이 “B”(bytecode 표기로 byte를 의미) 타입으로 byte 자료형임을 알 수 있다.

마지막으로 해당 thread가 수행중이었던 작업을 살펴 보면 아래와 같다.

Stacktrace 내용으로 알 수 있듯이 1.9GB 메모리를 요청한 Class/Method는 JEUS 엔진에서 사용되는 내부 모듈이며 정확히는 다음과 같다.

LoginInformation.readLoginInformation() (144라인)

그렇다면 이것은 JEUS 엔진 자체의 Bug 인가…?
지금까지 밝혀진 내용만으로도 충분히 가능성이 있지만, 좀 더 확실하게 접근하기 위해 소스 코드도 분석해 보자.

JEUS 엔진 내부 코드 분석 - class 역 컴파일

문제가 된 jeus 내부 모듈(LoginInformation.java)을 역컴파일해서 java 소스를 검토한 결과, 아래와 같이 144 라인에서 scope를 표현하기 위한 byte 자료형태의 memory를 요청하고 있었다.

자~ 지금까지 분석한 내용을 정리하면 다음과 같다.

FACT !!

• 문제 당시 1.5GB 이상의 여유로운 free memory가 존재했었음에도 OOME가 발생됨
  
• 특정 트랜잭션 하나가 한 번에 1.9GB의 memory를 요청하였음
  
• 1.9GB를 요청한 자료형은 byte 형태임
  
• 대용량 메모리를 요청한 Job은 JEUS 내부 모듈인 LoginInformation.java 임

이를 토대로 필자가 내린 결론은 다음과 같다.

전문가 판단 !!

• scope 정보를 나타내는 문자열은 몇 글자 안될 것임.
  (scope 종류 : page, request, session, application)
  (기껏해야 영문자 20 글자 이내? → 20 byte 정도 필요)
  
• scope 정보를 보관하는 LoginInformation class (this.scope 변수)가 1.9GB 크기의 메모리를 요청하는 것은 매우 비 이성적임
  
• LoginInformation class는 JEUS 내부 모듈이므로 JEUS Bug로 판단되며, 이에 대한 Tmax社의 해명이 필요함

이러한 결론을 내리고 과정과 결과를 정리하여 Tmax사에 이슈를 제기하였다.

Tmax社의 회신 내용 - JEUS Bug 인정

몇일 지나 최종적으로 받은 Tmax社의 회신 내용은 다음과 같았다.
(결론부터 말하자면 자사 제품에 Bug가 있었으니, 패치를 적용해 달라… 였다.)

Tmax 회신 내용
[ims171988] inquiry about OOM on JEUS Login Manager.

Jeus의 Session Manager 중복 로그인 기능 수행시 송신측에서 크게 설정한 byte array에 대해 수신측에서 정상적으로 deserialize 하지 못하는 이슈가 발생할 수 있습니다.
수신측에선 deserialize 을 정상적으로 수행하지 못하면 비정상적으로 큰 byte array을 new 요청하기 때문에 이럴 경우 OOM이 발생합니다.
이에, 송신측에서 필요한 byte array 만 송신 할수 있도록 내부 로직이 개선된 부분 패치를 제공하오니 적용 후 효과를 검증하시기 바랍니다.

결과적으론 제공받은 패치를 적용하여 문제가 깨끗이 해결되었으나, 해당 운영팀은 그동안 오픈 후 수개월간 본인들의 잘못없이 원인불명의 장애로 마음고생이 심했으리라…

심심한 위로를 표하고 싶다…

끗~