와탭 블로그

전체보기

JVM Crash 문제 해결하기

2019년 3월 15일

whatap_developer

웹 애플리케이션의 성능이 떨어지거나 장애가 발생한 경우 애플리케이션 성능 분석 서비스를 사용하면 애플리케이션의 내부 동작들을 속속들이 볼 수 있기에 대다수의 문제들을 해결할 수 있습니다. 와탭랩스는 애플리케이션의 성능 분석 서비스를 개발하는 회사이지만 고객사를 대신해서 직접 애플리케이션의 문제를 분석하고 해결하기도 합니다.

애플리케이션 문제 중에 많은 고객들이 힘들어하는 사례가 JVM Crash입니다. JVM Crash는 JVM 자체가 외부적인 요인으로 종료되는 경우이기 때문에 애플리케이션 성능 분석 서비스로 볼 수 있는 정보가 제한적이지만 대신 구글 검색과 IBM 사이트 등의 다양한 경로를 통해 해결할 수 있습니다. 그럼 JVM Crash 문제를 해결하는 방법을 알려드리도록 하겠습니다.

JVM Crash

jvm_crash

JVM(Java virtual machine)은 Java 프로그램이 실행되는 가상 머신입니다. 하나의 VM이므로 내부에서 시그널을 주지 않으면 종료되지 않도록 디자인되어 있습니다. 반대로 PC에서 간혹 만나는 블루 스크린과 같이 이유를 알 수 없이 멈추기도 합니다. 이 경우를 JVM에서는 Crash라고 합니다.

JVM Crash는 발생 빈도가 낮고 원인 또한 작성한 애플리케이션에서 기인하지 않으므로 개발자들이 원인을 규명하기 어려워합니다. 그러나 PC에서 만나는 블루 스크린 화면에도 에러코드, 메모리 주소가 나오는 것처럼 JVM 또한 죽기 전 실마리를 떨구고 갑니다.

JVM도 애플리케이션입니다.

jvm_also_application

애플리케이션은 모든 버그에 있어 평등합니다. 일정 규모 이상의 모든 애플리케이션은 중요하거나 사소한 Bug를 가지고 있습니다.

JVM 도 당연히 Bug가 있습니다. 그리고 그 버그가 Crash를 만들기도 합니다. 애플리케이션의 문제로 JVM에 Crash가 발생하는 것도 JVM의 문제입니다. 이 경우에도 정상적인 JVM이라면 애플리케이션의 오류를 친절하게 Exception, Error로 알려주고 Crash 되는 일은 없어야 합니다. JVM이 알 수 없는 사유로 Crash 된다면 그건 JVM Bug입니다.

다행인 것은 JDK 버그 픽스 리스트를 쉽게 찾아볼 수 있는 것입니다. IBM의 경우 유형별로 Crash, Hang, Performance 등으로 분류를 해 놓았습니다. 아래는 8.0 Fix Pack 리스트입니다. Defect Type을 보면 Crash, Issue, Hang 등으로 분류된 것을 볼 수 있습니다.

ij11480_crash_in_ffisys_call_in_zos

위 버그 수정 리스트에서 IJ11480: CRASH IN FFISYS CALL IN ZOS을 선택하면 아래와 같이 해당 버그에 대한 상세한 내용을 볼 수 있습니다.

물론 오라클에서도 버그 픽스 리스트를 관리하고 있습니다.

Oracle JDK Fix List 바로가기

JVM이 죽기 전에 남긴 에러 로그 찾아내기

JVM이 비정상 종료되면 hs_err_pid (hotspot), javacore (IBM) 을 남기도록 되어 있습니다. 하지만 로그 생성되지 않았거나 찾지 못하는 경우 관련 환경 변수, 옵션 등을 적용해 반드시 로그가 남을 수 있도록 해야 합니다.

로그 파일이 생성되는 위치를 알수 없을 경우 아래와 같이 로그파일을 작성할 위치를 지정해 줍니다.

오라클의 경우 product flag를 사용합니다.

                                -XX:ErrorFile=/var/log/java/hs_err_pid%p.log
                            
Java Platform, Standard Edition Troubleshooting Guide > Location of Fatal Error Log

IBM의 경우 .profile 환경 변수를 사용합니다.

                                export IBM_JAVACOREDIR=/somewhere/dumpdir
                            
Changing the location of javacore, heapdump and core file generated by TIP

그래도 로그가 남지 않는 경우라면 다음 상황을 의심할 수 있습니다.

  • /tmp usage full : /tmp 파일시스템이 다 찼다면 로그가 기록되지 않습니다.
  • 권한 문제 : java 프로세스를 구동 중인 계정이 대상 경로에 쓰기 권한이 없어도 로그가 기록되지 않습니다. 이 경우 JVM 옵션에 로그 경로를 설정합니다.
  • JVM Bug : JVM Crash도 버그, Crash 로그를 기록하지 못하는 것도 결국 JVM Bug입니다. 원인 규명이 매우 어렵습니다.

에러로그 보는 법

아래는 Oracle hotspot hs_err_pid 내용입니다. 상단에는 발생 사유와 발생 위치가 있습니다.

                                #
                                # A fatal error has been detected by the Java Runtime Environment:
                                #
                                # SIGSEGV (0xb) at pc=0x00007f06b22a991b, pid=6984, tid=0x00007f068a383700
                                #
                                # JRE version: OpenJDK Runtime Environment (8.0_121-b13) (build 1.8.0_121-b13)
                                # Java VM: OpenJDK 64-Bit Server VM (25.121-b13 mixed mode linux-amd64 compressed oops)
                                # Derivative: IcedTea 3.3.0
                                # Distribution: Custom build (Sat Jun 24 17:14:35 -03 2017)
                                # Problematic frame:
                                # V [libjvm.so+0x7c091b] Node::Node(unsigned int)+0x2b
                                #
                                # Core dump written. Default location: /build/java8-openjdk/src/icedtea-3.3.0/core or core.6984
                            

여기서 SIGSEGV는 Segmentation fault를 의미하고 Crash의 발생 사유 입니다.

    이외 대표적인 발생 사유로
  • 사용자의 kill -3 로 발생된 SIGQUIT
  • OOME(OutOfMemoryError) 로 발생된 Out of Memory Error
  • StackOverFlow 로 발생한 StackOverFlow
  • 등이 있습니다.

Problematic frame은 발생 위치를 나타냅니다.

위 예는 libjvm.so의 0x7c091b 위치에서 발생한 것으로 기록되어 있으므로 사용자가 구현한 영역의 오류가 아님을 알 수 있습니다.

같은 파일을 더 자세히 살펴보겠습니다.

                                Stack: [0x00007f068a283000,0x00007f068a384000], sp=0x00007f068a381550, free space=1017k
                                Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
                                V [libjvm.so+0x7c091b] Node::Node(unsigned int)+0x2b
                                V [libjvm.so+0x417363] Compile::Init(int)+0xd3
                                V [libjvm.so+0x41c38d] Compile::Compile(ciEnv*, TypeFunc const* (*)(), unsigned char*, char const*, int, bool, bool, bool)+0x6ad
                                V [libjvm.so+0x862cb6] OptoRuntime::generate_stub(ciEnv*, TypeFunc const* (*)(), unsigned char*, char const*, int, bool, bool, bool)+0xe6
                                V [libjvm.so+0x862e9b] OptoRuntime::generate(ciEnv*)+0x3b
                                V [libjvm.so+0x38b4d6] C2Compiler::init_c2_runtime()+0xa6
                                V [libjvm.so+0x38b535] C2Compiler::initialize()+0x25
                                V [libjvm.so+0x421d58] CompileBroker::init_compiler_runtime()+0x1a8
                                V [libjvm.so+0x428b65] CompileBroker::compiler_thread_loop()+0x115
                                V [libjvm.so+0x9062ad] JavaThread::thread_main_inner()+0x18d
                                V [libjvm.so+0x7e3e78] java_start(Thread*)+0xd8
                                C [libpthread.so.0+0x72e7] start_thread+0xd7
                            

Dump 내용을 확인해 보면, 0x7c091b는 Java Compiler 가 호출 한 Node인 것을 알 수 있습니다. Java bytecode를 기계어로 번역하는 과정에서 발생한 JVM 오류로 Crash가 발생했다고 판단할 수 있습니다.

IBM Java의 경우 javacore를 남깁니다. Oracle hotspot과 마찬가지로 상단에 발생 사유와 발생 위치가 있습니다.

                                0SECTION       TITLE subcomponent dump routine
                                NULL           ===============================
                                1TICHARSET     UTF-8
                                1TISIGINFO     Dump Event "gpf" (00002000) received
                                1TIDATETIME    Date: 2019/02/27 at 17:44:25:387
                                1TINANOTIME    System nanotime: 17387974755608115
                                1TIFILENAME    Javacore filename: ./dump/heapdump.2019-02-27_174423.hprof/javacore.20190227.174423.14483464.0003.txt
                                1TIREQFLAGS    Request Flags: 0x81 (exclusive+preempt)
                                1TIPREPSTATE   Prep State: 0x100 (trace_disabled)
                                1TIPREPINFO    Exclusive VM access not taken: data may not be consistent across javacore
                                sections
                                NULL           ------------------------------------------------------------------------
                                0SECTION       GPINFO subcomponent dump routine
                                NULL           ================================
                                2XHOSLEVEL     OS Level         : AIX 7.1
                                2XHCPUS        Processors -
                                3XHCPUARCH       Architecture   : ppc64
                                3XHNUMCPUS       How Many       : 16
                                3XHNUMASUP       NUMA is either not supported or has been disabled by user
                                NULL
                                1XHEXCPCODE    J9Generic_Signal_Number: 00000004
                                1XHEXCPCODE    Signal_Number: 0000000B
                                1XHEXCPCODE    Error_Value: 00000000
                                1XHEXCPCODE    Signal_Code: 00000032
                                1XHEXCPCODE    Handler1: 09001000A057A2B0
                                1XHEXCPCODE    Handler2: 09001000A05558D8
                                NULL
                                1XHEXCPMODULE  Module: /usr/java8_64/jre/lib/ppc64/compressedrefs/libj9thr29.so
                            

발생 사유인 Dump Event "gpf"는 general protection fault이며 Segmentation fault와 동일합니다.

역시 아래에는 Module: /usr/java8_64/jre/lib/ppc64/compressedrefs/libj9thr29.so라는 발생 위치가 기록되어 있습니다.

구글에게 물어보기

크래시 원인이 SIGSEGV(Segmentation fault) 또는 gpf(general protection fault)이고 발생 위치가 JDK 내부 모듈이라면 JDK Fix를 통해 문제를 해결하면 됩니다.

오라클 Hotspot의 로그를 통해 libjvm.so의 0x7c091b에서 오류가 발생했다는 것을 확인했다면 이제 구글에서 해당 라인을 검색합니다.

                                # Problematic frame:
                                # V [libjvm.so+0x7c091b] Node::Node(unsigned int)+0x2b
                            
google_search_0x7c091b

검색을 하면 해당 라인의 버그를 확인해 볼 수 있습니다. 상태 값이 CLOSED입니다. 해당 버그 픽스를 찾으면 됩니다. https://bugs.openjdk.java.net/browse/JDK-8183197

하단에 Comments를 확인합니다. 버그 픽스에 대한 링크를 찾을 수 있습니다.

bug_openjdk_java_net_activity_comment

아래 링크에서 좀더 자세한 정보를 찾을 수 있습니다. https://bugzilla.redhat.com/show_bug.cgi?id=1306558

bugzilla_redhat_com

이제 해당 JDK 버전 이후의 Fix List를 검토하고 업데이트 계획을 세우면 됩니다. 다만 업데이트를 계획하는 대신 해당 버그의 원인을 기반으로 애플리케이션의 구조를 변경하여 문제를 회피하는 방법을 사용해 볼 수도 있습니다. 이런 경우 애플리케이션 성능 분석 도구가 도움이 될 수 있습니다.

마무리

JDK 역시 누군가 만든 애플리케이션입니다. JDK도 오류 가능성을 내포하고 있다는 것을 항상 인지하고 주기적인 업데이트를 통해 더 안정적인 환경을 만들어 나가야 합니다. 그리고 애플리케이션의 성능을 올려야 하거나 애플리케이션에서 발생한 문제가 해결되지 않는다면 와탭랩스(support@whatap.io)에 연락 주세요. 최대한 도와드리도록 하겠습니다.

송재진(jjsong@whatap.io)
WAS 전문가이자 와탭의 프리세일즈 컨설턴트
<  이전 글

다음 글  >

최신글