Javax Activation Bug에 의한 WAS Hang 현상 - WAS Troubleshooting 사례(2)
Updated:
Javax Activation Bug에 의한 WAS Hang 현상 - WAS Troubleshooting 사례(2)
OO 홈쇼핑은 고객의 트랜잭션을 처리하기 위해 총 16대의 WebLogic instance를 clustering 구성해 놓았다.
문제는 16대의 WebLogic instance가 1~2일에 한 번씩 Hang-up 현상에 빠지며 서비스 장애를 일으키고 있는데, 아무도 정확한 원인을 파악하지 못해 오픈한지 10년째 WebLogic 재기동으로만 조치하고 있어 서비스 안정성이 불안정하다는 것이다.
과연 무엇이 문제이고 어떤 방법으로 해결할 수 있을지 같이 알아 보도록 하자.
원인 파악을 위한 로그 분석 - GC log, Heap 덤프
Java 쓰레드 덤프는 모든 JVM 관련 issue를 파악하기 위한 기본이 된다.
또한 Heap 덤프와 GC log는 JVM의 모든 Memory 관련 issue를 파악하기 위한 기본이 된다.
운영 담당자를 인터뷰해 본 결과, 장애 시점에 WebLogic log 상으로 OutOfMemoryError가 발생하며, 본인들이 Heap 덤프도 분석해 보았는데도 정확한 원인을 모르겠다는 것이다.
WebLogic log 상으로 OutOfMemoryError가 발생한다고 하니 일단 Memory 사용 추이를 GC log를 통해 알아 보기로 했다.
참고로, GC log는 WAS 기동 시 JAVA OPTIONS로 아래와 같은 설정을 추가하면 생성할 수 있다.
-Xlog:gc*:file=<gc_filename>
기존 에러시점에 생성된 GC log를 분석용 도구를 이용하여 그래프화 하였더니 아래와 같이 나타났다.
일반적으로 OutOfMemoryError가 발생하는 원인은 크게 2가지 유형으로 구분되어 진다.
첫 번째 유형은 지속적인 메모리 누수로 특정 프로그램에서 장시간에 걸쳐 메모리를 조금씩 잠식하여 최종적으로 OutOfMemoryError가 발생하는 것이며, 두 번째 유형은 대용량 데이터 조회 혹은 대용량 엑셀 다운로드 등 트랜잭션 처리에 Huge Memory가 필요한 Request가 수행되는 경우이다.
GC 그래프를 보면 시간이 지남에 따라 가용 Heap Memory가 점차 줄어들어 최종적으로 WAS가 Hang-up 상태에 빠진 것을 추정할 수 있어 이번 CASE에서는 OutOfMemoryError가 발생하는 유형이 전형적인 첫 번째 유형이었다.
대체적으로 이런 유형은 Heap 덤프 파일을 획득하여 분석해 보면 어느 프로그램에서 지속적인 메모리 누수가 발생하는지 알 수 있다.
운영 담당자에게 WAS 서버 Hang-up이 발생한 과거 3번의 Heap 덤프파일을 받아 분석해 보았다.
Heap 덤프 분석 결과, 아래와 같이 WebLogic Server 內 특정 모듈(RuntimeAccessImpl)에서 전체 Heap Memory의 약 57%(1GB)를 소모하고 있었다.
WebLogic Server 內 특정 모듈이 왜 이렇게 많은 Memory를 차지하고 있는지 추가분석을 진행하였더니, 아래와 같이 java.lang.Thread 객체가 배열형태로 약 670MB 메모리를 점유 중인 것이 파악되었다.
보통은 애플리케이션 개발자가 개발한 Java Class가 메모리를 점유한 모습이 나와야 하는데, 여기서는 WebLogic의 내부 모듈이 메모리를 왕창 점유한 모습이 나온 것이다. 그렇다면 이 것은 WebLogic Bug 인가….?
뭔가 추가적인 분석이 더 필요해 보인다…
Root Cause를 밝혀내기 위한 추가 로그 분석 - Java 쓰레드 덤프
메모리를 점유하고 있는 객체가 WebLogic 내부 모듈이라고 하여 WebLogic Bug로 단정지을 수 없어 해당 장애 시점의 Thread 덤프를 추가적으로 분석해 보았다.
분석 내용은 다음과 같다.
쓰레드 덤프를 살펴 보면 해당 덤프는 OutOfMemoryError가 발생된 상태에서 남겨진 쓰레드 덤프가 맞으며 Heap 메모리 정보를 보면 2GB가 할당되었지만, 현재 남아 있는 Free 영역은 24D7D0(=약 2MB) 뿐이 남아 있지 않음을 알 수 있다.
특이한 점은, 보통 JVM 內 전체 Thread 개수가 많아도 2~300 개 인데 반해, 본 쓰레드 덤프에는 Total 7,873개의 쓰레드가 존재하며 이로 인해, “Insufficient stack space for native stack collection” 오류가 발생했다는 점이다.
도데체, JVM 內에서 무슨 일을 하고 있길래 7천개가 넘는 어마무시한 Thread들이 생성이 되었을까…
Java Email API - DataHandler
7천개가 넘는 쓰레드가 무슨일을 하는지 살펴보니, 대부분이 “DataHandler.getInputStream”이라는 중복된 쓰레드 이름으로 다수 발견되었으며 아래 그림과 같이 Total 7,651개가 존재하였다.
“DataHandler”에 대해 검색해 보니 이메일 발송을 위해 사용되는 Class로 javax.activation의 package 형태로 제공되어 지는 것이었다.
아래는 javax.activation의 DataHandler Source Code의 일부분이다.
정상적인 경우라면 본문을 작성하자 마자 해당 Thread는 종료(Disapear)되어야 하나, 어떤 이유에서인지 본 시스템에서는 해당 Thread가 종료되지 못하고 계속 남아 Zombi Thread 化 되어 있는 것이 문제였다.
DataHandler Thread가 지속적으로 생성되어 종료되지 못하고 점차 누적 → 점진적 메모리 잠식 → 홈쇼핑 WAS Instance Hang-up
운영담당자도 몰랐던 사항 - 舊 버전의 모듈 사용
그렇다면 왜 이런 현상(DataHandler의 비정상 Zombi Thread)이 발생하는 걸까?
원인 파악을 위해 사용중인 javax.activation의 버전을 확인해 보다가 이상한 점을 발견했다. 동일한 javax.activation jar가 버전을 달리하여 2가지가 상존하고 있는 것이 아닌가…
버전 하나는 1.1.0이고 다른 하나는 1.4.5였다. 그 중에서 실제로 WebLogic에서 기동되고 있는 모듈(jar)은 1.1.0으로 매우 오래된 구형 버전인 것이다.
운영담당자에게 이러한 상황을 알려주니, 전혀 몰랐던 사항이며 당연히 최신 버전을 사용하고 있는줄 알고 있었다는 것이다.
그렇다면 추측컨데, 문제가 되고 있는 현상은 javax.activation의 오래된 구 버전에서 발생할 수 있는 Bug 가능성이 있으며 최신 업데이트 버전을 적용하여 해당 현상이 개선되는지 확인해 보면 명확한 Root Cause인지 판단할 수 있을 것으로 생각했다.
최신 버전으로의 적용은 WebLogic이 기동 시 기존에 있던 1.1.0 버전 대신 1.4.5 버전의 jar를 읽어들일 수 있도록 PRE CLASSPATH로 지정해 주는 방법을 사용하였다.
개선사항 적용 및 효과 검증 모니터링
OO 홈쇼핑은 현재 총 4대의 서버, 16개 WAS Instance(서버당 4 Instance)로 운영중이었다.
물론 운영서버 적용 전에 개발/검증서버에서 개선효과 및 기능검증을 완료하였으나 보다 보수적인 운영 안정성을 위해 시범적으로 1대 운영서버, 4개 WAS Instance를 대상으로만 개선내역을 반영하고 나머지 미적용한 3대와 비교해 보기로 하였다.
결과적으로, 개선사항 적용 후 주말(토,일) 동안 최신 버전의 javax.activation jar를 적용한 1대 서버(4대 WAS Instance)는 메모리 누수나 재기동 없이 원활한 서비스를 보인 반면, 개선 내역을 반영 안한 나머지 3대 서버는 기존과 동일한 메모리 누수 및 Hang-up 현상이 발생하여 평소와 마찬가지로 강제 재기동을 수행하였다.
아래 그래프처럼 메모리 사용량 추이 그래프로도 개선 전/후 효과를 확연하게 확인이 가능하였다.(메모리 누수 현상 제거됨)
끗~