jvm 버그 테스트 하는방법! (java heap memory)

고맙다 JVM, 사과해라 JVM 크래시

많은 개발자가 버그 원인을 인프라 탓으로 돌리곤 합니다. 전혀 이상이 없는 것 같은데 버그가 발생하니 애꿎은 장비나 DBMS(database management system), JVM(Java virtual machine)을 탓하는 것입니다. 하지만 거의 대부분, 아마도 99.9%는, 인프라의 잘못이 아닙니다. 그러나 이 글에서는 JVM 실행이 멈춘, 0.1%에 해당될 만한 이야기를 하려 합니다. JVM의 실행이 멈췄다는 것은 0.1%라고 무시할 수 없는 사례입니다.

JVM은 마치 자동차의 엔진과 같은 것이라 인위적으로 시동을 끄지 않는 이상(System.exit 등) 외부적인 요인으로 실행이 멈추면 안 됩니다. JVM이 멈춘다는 것은 단순히 특정 시간의 장애로만 끝나는 것이 아닙니다. 근본 해결이 없다면 상습적인 장애로 연결돼 불안정한 서비스라 낙인이 찍히고 사용자는 이 불안정한 서비스를 외면할 것입니다.

JVM에 버그가 있어 예기치 않는 종료가 발생하면 어떻게 Java로 개발할 수 있을까요? 이 글에서는 JVM 크래시 현상에 대한 경험과 발생 원인을 분석한 과정을 공유하려 합니다.

JVM 오류 현상

얼마 전 한 서비스에 신규로 도입한 서버의 성능을 테스트할 때 문제가 발생해 해결 방법을 고민한 적이 있다. 가상 사용자가 120명을 넘으면 Tomcat의 실행이 중단되는 현상이 발생한 것이다. 성능 테스트 결과를 정리한 표 1에서 가상 사용자 정보가 120 이상이 없는 것은 이러한 이유 때문이다.

표 1 신규 서버 성능 테스트 결과

가상 사용자	TPS	평균 응답	CPU%	DB CPU%
10	10	0.08	15	2
20	20	0.09	23	2
30	30	0.09	28	3
40	40	0.1	39	4
50	50	0.11	46	6
60	60	0.13	51	5
70	70	0.15	61	6
80	80	0.16	63	6
90	90	0.26	72	7
100	100	0.35	78	8

가상 사용자가 120명을 넘으면 Tomcat 실행이 중단되는 이유는 JVM이 기록하는 크래시 로그인 hs_err_pid 파일로 분석할 수 있었다. hs_err_pid 파일에는 스택 트레이스(stack trace) 정보가 있어 장애 당시의 상황을 알 수 있다.

JVM의 명백한 버그

JVM 크래시 로그를 보기 전에 hs_err_pid 파일의 주요 구성 항목을 간단히 설명하면 다음과 같다. hs_err_pid 파일에 관한 더 자세한 설명은 "Troubleshooting and Diagnostic Guide" 문서를 참고한다.

표 2 hs_err_pid 파일의 주요 구성 항목

구성 항목	설명
Header	오류에 관한 간략한 정보가 기술된 영역. 프로세스 아이디, 스레드 아이디, VM버전, 크래시를 일으킨 function frame정보 등이 있다.
Thread	크래시 발생 당시의 스레드 관련 정보
Process	모든 프로세스에 대한 정보. 이 프로세스에는 스레드 목록과 메모리 사용량에 대한 정보가 있다.
System	운영체제 버전, CPU정보, 메모리 설정 관련 정보 등

다음은 성능 테스트 시의 JVM 크래시 로그 중 크래시 당시의 스레드가 무엇인지 알려 주는 정보다.

#
# A fatal error has been detected by the Java Runtime Environment:
#  SIGSEGV (0xb) at pc=0xb7961e23, pid=11757, tid=1405516688
#
# JRE version: 6.0_18-b07
# Java VM: Java HotSpot(TM) Server VM (16.0-b13 mixed mode linux-x86 )
# Problematic frame:
# V  [libjvm.so+0x5a2e23]
#
# If you would like to submit a bug report, please visit:
#   http://java.sun.com/webapps/bugreport/crash.jsp

---------------  T H R E A D  ---------------

Current thread (0x09a57400):  GCTaskThread [stack: 0x53be7000,0x53c68000] [id=11760]

제일 먼저 확인해야 할 부분은 Thread 섹션에서 JVM 크래시 순간의 스레드가 무엇인지다. 위와 같이 가비지 컬렉션(garbage collection) 스레드의 특수한 경우라면 가비지 컬렉션 자체에 문제가 있지 않나 의문을 가질 수 있으나 판단을 내리기에는 정보가 부족하다.

다음 로그를 보도록 하자.

Heap
PSYoungGen      total 282176K, used 275243K [0x9ecf0000, 0xb4240000, 0xb4240000)
eden space 214336K, 100% used [0x9ecf0000,0xabe40000,0xabe40000)
from space 67840K, 89% used [0xb0000000,0xb3b7ad00,0xb4240000)
to   space 67328K, 43% used [0xabe40000,0xadae6ba0,0xb0000000)
PSOldGen        total 699072K, used 299948K [0x74240000, 0x9ecf0000, 0x9ecf0000)
object space 699072K, 42% used [0x74240000,0x8672b218,0x9ecf0000)
PSPermGen       total 524288K, used 42358K [0x54240000, 0x74240000, 0x74240000)
object space 524288K, 8% used [0x54240000,0x56b9d808,0x74240000)

Java의 힙 메모리 영역 중 Eden 영역(eden space)이 100%라는 정보를 볼 수 있다. Oracle JVM 에서는 새로 생성됐거나 생성된 지 얼마 되지 않은 객체는 Eden 영역에 저장된다. Eden 영역이 일정 비율 이상 차면 설정에 따라 가비지 컬렉션이 발생하고, 계속 생성돼 있을 필요가 있는 객체는 S0(from)라는 Survivor 영역으로 옮겨진다. 다시 Eden 영역이 차면 S1(to)이라는 또 다른 Survivor 영역으로 이동한다. 설정에 따라 조금씩 동작 방법이 다르지만 좀 더 오래 생성돼 있어야 하는 객체는 가비지 컬렉션을 거치면서 Old 영역으로 이동한다.

따라서 앞의 힙 트레이스(heap trace)에서 Eden 영역이 100%인 것은 문제가 아니며 절대 메모리 부족으로 오해하면 안 된다. 문제는 from 영역과 to 영역에서 확연히 보인다. S0(from)와 S1(to) 중 하나의 영역은 반드시 비어 있어야 하는데(그림 1 참고), 크래시 로그에서 메모리 영역의 from 영역과 to 영역은 각각 89%와 43%다. 즉 가비지 컬렉션이 기대대로 동작하지 않은 것이다.

지금까지의 정보를 바탕으로 단순하지만 중요한 JVM 크래시 시나리오가 나올 수 있다. '가비지 컬렉션 중 JVM 크래시가 발생했으며, Eden 영역에서 Survivor 영역으로 객체를 옮기는 Eden GC 매커니즘에 문제가 있어 JVM 크래시가 발생했다.'

그림 1 JVM Heap Space 구조

버그 리포트와 릴리스 노트

여기까지 분석이 끝났다면 다음이 중요하다. 물론 JVM 크래시 로그의 전체 내용을 분석하지는 않았지만 중요한 단서를 얻었으므로 그냥 여기서 끝낼 수도 있다. 그러나 그렇게 끝낸다면 지금까지의 분석은 아무런 의미가 없을 것이다. 정석대로라면 다음에 할 작업은 추측한 시나리오를 바탕으로 JVM 버전의 버그 정보를 조회하는 것이다.

문제가 발생한 JVM 버전은 6.0_18(b07) 버전이었다(6.0_18(b07) 버전 버그 리포트 참고). 이 버그와 관련된 버그가 JVM 7.0-b74에서 발생했으며, 자세한 버그의 내용은 JVM 7.0-b74의 버그 리포트에서 확인할 수 있었다.

버그 내용을 간단하게 요약하면 가비지 컬렉션 수행 중에 쓰레기로 판단된 객체에 대한 표시(marking)가 제때 이루어지지 않고 오래 걸릴 수 있는 문제가 있다는 것이다. 즉, 가비지 컬렉션 알고리즘 중에 하나인 표시 제거(mark-sweep) 방식으로 쓰레기 객체를 표시(marking)해 제거하고 공간 단편화를 진행할 때 문제가 발생한다는 것이다. 지금은 이를 해결한 버전이 나왔고 6.0_18(b9)에도 적용됐다. 그러나 그 당시에는 근본 해결책은 없었고 대안으로 JVM 실행 옵션에 '-XX:-ReduceInitialCardMarks'를 추가해 회피하라는 설명이 있었다.

여기까지 왔다면 개발자의 성향에 따라 2가지 방법 중 하나를 선택한다. 버그 리포트에서 설명하는 JVM 옵션을 추가해 사용하거나, 안정된 JVM 버전으로 다운그레이드하는 것이다. 결국 신규 서버를 기존 서버가 사용하는 6.0_14 버전으로 다운그레이드하고 성능 테스트를 다시 실행했더니 가상 사용자 200에서 시스템의 작동이 중단되거나 중지되는 현상 없이 10여 분 동안 서비스가 지속됐다. 추측도 어느 정도 맞았고 성능 테스트도 해결돼 모든 게 잘 완료됐다고 볼 수 있지만 추가로 더 확인할 것이 있다.

추가로 확인할 것은 릴리스 노트다. 6.0_18 버전의 정식 릴리스 노트에서 관련 버그가 소개됐는지 확인하고 6.0_14 버전에도 문제가 없는지 확인하는 것이다. 6.0_18 버전의 릴리스 노트에 관련 내용이 있었다. 다음은 릴리스 노트에서 이 버그와 관련된 부분이다.

A flaw in the implementation of a card-marking performance optimization in the JVM can cause heap corruption under some circumstances. This issue affects the CMS garbage collector prior to 6u18, and the CMS, G1 and Parallel Garbage Collectors in 6u18. The serial garbage collector is not affected. Applications most likely to be affected by this issue are those that allocate very large objects which would not normally fit in Eden, or those that make extensive use of JNI Critical Sections (JNI Get/Release*Critical).

JVM에서 카드 표시 알고리즘의 성능을 최적화하는 데 결함이 있어 어떤 상황에서는 힙 영역에서 문제가 발생할 수 있다. 6u18 이전 버전의 CMS GC에 영향을 미치고, 6u18에서는 CMS GC와 G1 GC, Parallel GC에 영향을 미친다. Serial GC에는 영향이 없다. 이 문제에 가장 큰 영향을 받는 애플리케이션은 Eden 영역에 맞지 않는 매우 큰 객체를 할당하거나 JNI 크리티컬 섹션을 광범위하게 사용하는 애플리케이션이다.

요점만 정리하면 6.0_18 이전 버전의 CMS GC에 결함이 있어 Eden 영역에 너무 큰 객체가 할당되면 문제가 발생할 수 있다는 것이다. JVM 크래시 로그를 보고 만든 시나리오가 모두 맞아 환호성을 지를 수도 있겠으나 분석과 추측이 맞았다고 근본적인 문제가 해결된 것은 아니다.

마치며

이 글에서 이야기한 Oracle JVM은 웹 기반의 서비스를 개발할 때 많이 사용하는 프리웨어 소프트웨어의 일종이다. Oracle이라는 큰 제조사에서 생산하는 소프트웨어에도 버그가 있다는 것을 명심하고 검증 과정을 거쳐 사용해야 하겠다. 특히 최신 버전일수록 검증 과정의 중요성은 더욱 높다.

무료 소프트웨어나 오픈소스는 누구나 사용할 수 있지만 누구나의 것은 아니다. 태생 자체가 무료임을 알고 버그가 있는지 확인하고 잠재된 문제가 있는지 테스트하면서 상황에 맞게 사용하는 개발자의 것이다. 또한 발견된 문제와 해결 방안을 공유해 더 안정된 소프트웨어나 오픈소스로 만들려는 사람들의 것이다.