JVM Error file(crash report)

자바 어플리케이션에 문제가 있어 아무 말 없이 종료되버리면 개발자 입장에선 난감하기 그지없다.
오류라도 뿜어주면 고맙겠지만, 아무도 오류메시지를 보지 못했다면 어디서 그의 죽음에 관한 정보를 얻을 수 있을것이며, 그 오류는 어떻게 찾아 고쳐야 할까?

다행히 JVM은 자바 어플리케이션에서 심각한 오류나, 예상하지 못한 오류를 발견 했을때는 자동적으로 STDOUT에 dying message 를 남기고, 어플리케이션의 실행위치에 error report 파일을 작성한다는데...

진짜 그런지 한번 보자.
아래는 강제로 에러를 발생시키는 자바 어플리케이션이다.

public class ForceDump {

public static void main( String[] args ) throws Exception
{

java.lang.reflect.Field field = sun.misc.Unsafe.class.getDeclaredField("theUnsafe");

        field.setAccessible(true);

        sun.misc.Unsafe $ = (sun.misc.Unsafe) field.get(null);

        $.putAddress(0, 0);

    }

}

이걸 실행해보면 다음과 같은 결과가 출력된다. 빨간색 글자로 범인은 누구라고 알려준다. 뿐만 아니라 어플리케이션 종료 당시의 해당 어플리케이션의 실행정보를 가지고 있는 에러파일을 저장했다고 한다.

D:\dev\lab\Test\bin>java ForceDump

#

# A fatal error has been detected by the Java Runtime Environment:

#

#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006d9b9565, pid=4568, tid=6248

#

# JRE version: 6.0_25-b06

# Java VM: Java HotSpot(TM) 64-Bit Server VM (20.0-b11 mixed mode windows-amd64 compressed oops)

# Problematic frame:

# V  [jvm.dll+0x1c9565]

#

# An error report file with more information is saved as:

# D:\dev\lab\Test\bin\hs_err_pid4568.log

#

# If you would like to submit a bug report, please visit:

#   http://java.sun.com/webapps/bugreport/crash.jsp

#

자세한 에러 파일 내용을 보기 전에 잠깐,

에러파일이 hs_err_pid<PID>.log 라는 이름으로 java 어플리케이션이 실행된 경로에 생겨있다. 파일이름과 생기는 위치는 이와 같은 형태가 기본값이지만, 이 파일의 이름과 위치를 바꾸려면 다음과 같이 옵션을 주면 된다.
 

D:\dev\lab\Test\bin>java -XX:ErrorFile=../err_file_pid_%p.log ForceDump
#

# A fatal error has been detected by the Java Runtime Environment:

#

#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006d9b9565, pid=3088, tid=1340

#

# JRE version: 6.0_25-b06

# Java VM: Java HotSpot(TM) 64-Bit Server VM (20.0-b11 mixed mode windows-amd64 compressed oops)

# Problematic frame:

# V  [jvm.dll+0x1c9565]

#

# An error report file with more information is saved as:

# ../err_file_pid_3088.log

#

# If you would like to submit a bug report, please visit:

#   http://java.sun.com/webapps/bugreport/crash.jsp

#

-XX:ErrorFile=<filename> 형식이며 filename에 %p 를 쓰면 해당 어플리케이션의 pid 값으로 치환된다.
filename 은 상대 또는 절대경로를 포함해 지정 할 수 있다. (위 예시에서는 상대경로를 지정해보았다.)
만일 유효하지 않은 경로라면 이 옵션을 지정하지 않은 것과 동일하게 동작한다.



아래는 범인에 대한 더 많은 정보를 가지고 있다는 에러파일의 내용이며, 왜 프로그램이 종료 되었는지에 대해 분석하는데 도움이 된다.

#

# A fatal error has been detected by the Java Runtime Environment:

#

#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006d9b9565, pid=4648, tid=5064

#

# JRE version: 6.0_25-b06

# Java VM: Java HotSpot(TM) 64-Bit Server VM (20.0-b11 mixed mode windows-amd64 compressed oops)

# Problematic frame:

# V  [jvm.dll+0x1c9565]

#

# 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 (0x00000000003eb000):  JavaThread "main" [_thread_in_vm, id=5064, stack(0x00000000023f0000,0x00000000024f0000)]

siginfo: ExceptionCode=0xc0000005, writing address 0x0000000000000000

Registers:

RAX=0x0000000000000000, RBX=0x00000000003eb000, RCX=0x0000000000000b00, RDX=0x00000000024efa18

RSP=0x00000000024ef910, RBP=0x00000000024ef9d8, RSI=0x0000000000000000, RDI=0x0000000000000000

R8 =0x0000000000000000, R9 =0x0000000000000000, R10=0x0000000002501359, R11=0x000000006d9f24f0

R12=0x0000000000000000, R13=0x000000077aec9b80, R14=0x00000000024efa18, R15=0x00000000003eb000

RIP=0x000000006d9b9565, EFLAGS=0x0000000000010246

Top of Stack: (sp=0x00000000024ef910)

0x00000000024ef910:   00000000024efa60 0000000002501212

0x00000000024ef920:   000000077aec9b80 00000000024ef9d8

0x00000000024ef930:   00000000024f59c9 000000077b0e05e8

0x00000000024ef940:   000000077aec9b80 0000000002501386

0x00000000024ef950:   00000007000000b6 00000000003eb9f0

0x00000000024ef960:   00000000003e74d0 00000000003eb5d0

0x00000000024ef970:   00000000003eb5e0 00000000003eb9b8

0x00000000024ef980:   0000000000000000 00000000003eb000

0x00000000024ef990:   0000000000000000 00000000024ef998

0x00000000024ef9a0:   000000077aec9b80 00000000024efa18

0x00000000024ef9b0:   000000077aeccbe0 0000000000000000

0x00000000024ef9c0:   000000077aec9b80 0000000000000000

0x00000000024ef9d0:   00000000024ef9f8 00000000024efa60

0x00000000024ef9e0:   00000000024f5b22 0000000000000000

0x00000000024ef9f0:   00000000024fe358 0000000000000000

0x00000000024efa00:   00000000024efa60 0000000000000000 

Instructions: (pc=0x000000006d9b9565)

0x000000006d9b9545:   85 c0 75 0a 8b 43 30 a9 00 00 00 30 74 08 48 8b

0x000000006d9b9555:   cb e8 35 de 04 00 c7 83 48 02 00 00 06 00 00 00

0x000000006d9b9565:   48 89 3e 48 8b 7b 48 48 8b 4f 10 48 8b 77 08 48

0x000000006d9b9575:   83 39 00 74 05 e8 91 db ed ff 48 8b 47 10 48 89 

Register to memory mapping:

RAX=0x0000000000000000 is an unknown value

RBX=0x00000000003eb000 is a thread

RCX=0x0000000000000b00 is an unknown value

RDX=0x00000000024efa18 is pointing into the stack for thread: 0x00000000003eb000

RSP=0x00000000024ef910 is pointing into the stack for thread: 0x00000000003eb000

RBP=0x00000000024ef9d8 is pointing into the stack for thread: 0x00000000003eb000

RSI=0x0000000000000000 is an unknown value

RDI=0x0000000000000000 is an unknown value

R8 =0x0000000000000000 is an unknown value

R9 =0x0000000000000000 is an unknown value

R10=0x0000000002501359 is an Interpreter codelet

method entry point (kind = native)  [0x00000000025010e0, 0x0000000002501960]  2176 bytes

R11=0x000000006d9f24f0 is an unknown value

R12=0x0000000000000000 is an unknown value

R13=0x000000077aec9b80 is an oop

{method} 

 - klass: {other class}

R14=0x00000000024efa18 is pointing into the stack for thread: 0x00000000003eb000

R15=0x00000000003eb000 is a thread

Stack: [0x00000000023f0000,0x00000000024f0000],  sp=0x00000000024ef910,  free space=1022k

Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)

V  [jvm.dll+0x1c9565]

j  ForceDump.main([Ljava/lang/String;)V+25

v  ~StubRoutines::call_stub

V  [jvm.dll+0x1e9a17]

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)

j  sun.misc.Unsafe.putAddress(JJ)V+0

j  ForceDump.main([Ljava/lang/String;)V+25

v  ~StubRoutines::call_stub

---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )

  0x0000000006882000 JavaThread "Low Memory Detector" daemon [_thread_blocked, id=5808, stack(0x0000000006e20000,0x0000000006f20000)]

  0x000000000687f000 JavaThread "C2 CompilerThread1" daemon [_thread_blocked, id=5676, stack(0x0000000006d20000,0x0000000006e20000)]

  0x000000000687d800 JavaThread "C2 CompilerThread0" daemon [_thread_blocked, id=3376, stack(0x0000000006c20000,0x0000000006d20000)]

  0x0000000006832800 JavaThread "Attach Listener" daemon [_thread_blocked, id=6908, stack(0x0000000006b20000,0x0000000006c20000)]

  0x000000000682d000 JavaThread "Signal Dispatcher" daemon [_thread_blocked, id=7036, stack(0x0000000006a20000,0x0000000006b20000)]

  0x000000000052b800 JavaThread "Finalizer" daemon [_thread_blocked, id=6240, stack(0x0000000006720000,0x0000000006820000)]

  0x0000000000524800 JavaThread "Reference Handler" daemon [_thread_blocked, id=5944, stack(0x0000000006620000,0x0000000006720000)]

=>0x00000000003eb000 JavaThread "main" [_thread_in_vm, id=5064, stack(0x00000000023f0000,0x00000000024f0000)]

Other Threads:

  0x000000000051d000 VMThread [stack: 0x0000000006520000,0x0000000006620000] [id=5052]

  0x0000000006893000 WatcherThread [stack: 0x0000000006f20000,0x0000000007020000] [id=1560]

VM state:not at safepoint (normal execution)

VM Mutex/Monitor currently owned by a thread: None

Heap

 PSYoungGen      total 38208K, used 655K [0x00000007d5560000, 0x00000007d8000000, 0x0000000800000000)

  eden space 32768K, 2% used [0x00000007d5560000,0x00000007d5603d80,0x00000007d7560000)

  from space 5440K, 0% used [0x00000007d7ab0000,0x00000007d7ab0000,0x00000007d8000000)

  to   space 5440K, 0% used [0x00000007d7560000,0x00000007d7560000,0x00000007d7ab0000)

 PSOldGen        total 87424K, used 0K [0x0000000780000000, 0x0000000785560000, 0x00000007d5560000)

  object space 87424K, 0% used [0x0000000780000000,0x0000000780000000,0x0000000785560000)

 PSPermGen       total 21248K, used 2964K [0x000000077ae00000, 0x000000077c2c0000, 0x0000000780000000)

  object space 21248K, 13% used [0x000000077ae00000,0x000000077b0e5268,0x000000077c2c0000)

Code Cache  [0x00000000024f0000, 0x0000000002760000, 0x00000000054f0000)

 total_blobs=154 nmethods=0 adapters=121 free_code_cache=49951040 largest_free_block=0

Dynamic libraries:

0x0000000000400000 - 0x000000000042e000 C:\Windows\system32\java.exe

0x0000000077be0000 - 0x0000000077d89000 C:\Windows\SYSTEM32\ntdll.dll

0x0000000077500000 - 0x000000007761f000 C:\Windows\system32\kernel32.dll

0x000007fefe0f0000 - 0x000007fefe15c000 C:\Windows\system32\KERNELBASE.dll

0x000007feffb50000 - 0x000007feffc2b000 C:\Windows\system32\ADVAPI32.dll

0x000007fefeb10000 - 0x000007fefebaf000 C:\Windows\system32\msvcrt.dll

0x000007fefe8c0000 - 0x000007fefe8df000 C:\Windows\SYSTEM32\sechost.dll

0x000007fefe8e0000 - 0x000007fefea0d000 C:\Windows\system32\RPCRT4.dll

0x000000006d7f0000 - 0x000000006dfa8000 C:\Program Files\Java\jre6\bin\server\jvm.dll

0x0000000077770000 - 0x000000007786a000 C:\Windows\system32\USER32.dll

0x000007feffc30000 - 0x000007feffc97000 C:\Windows\system32\GDI32.dll

0x000007feffb40000 - 0x000007feffb4e000 C:\Windows\system32\LPK.dll

0x000007feffd80000 - 0x000007feffe49000 C:\Windows\system32\USP10.dll

0x000007fefca70000 - 0x000007fefcaab000 C:\Windows\system32\WINMM.dll

0x000007feffd50000 - 0x000007feffd7e000 C:\Windows\system32\IMM32.DLL

0x000007fefe760000 - 0x000007fefe869000 C:\Windows\system32\MSCTF.dll

0x000000006d760000 - 0x000000006d76e000 C:\Program Files\Java\jre6\bin\verify.dll

0x000000006d3b0000 - 0x000000006d3d7000 C:\Program Files\Java\jre6\bin\java.dll

0x0000000077db0000 - 0x0000000077db7000 C:\Windows\system32\PSAPI.DLL

0x000000006d7b0000 - 0x000000006d7c2000 C:\Program Files\Java\jre6\bin\zip.dll

VM Arguments:

java_command: ForceDump

Launcher Type: SUN_STANDARD

Environment Variables:

CLASSPATH=.;C:\Program Files (x86)\Java\jre6\lib\ext\QTJava.zip

PATH=C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\TortoiseSVN\bin;C:\Program Files (x86)\QuickTime\QTSystem\

USERNAME=Alex

OS=Windows_NT

PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 23 Stepping 10, GenuineIntel

---------------  S Y S T E M  ---------------

OS: Windows 7 Build 7601 Service Pack 1

CPU:total 4 (4 cores per cpu, 1 threads per core) family 6 model 23 stepping 10, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3, sse4.1

Memory: 4k page, physical 8387064k(2644316k free), swap 16772280k(9635388k free)

vm_info: Java HotSpot(TM) 64-Bit Server VM (20.0-b11) for windows-amd64 JRE (1.6.0_25-b06), built on Apr 14 2011 00:44:38 by "java_re" with MS VC++ 8.0 (VS2005)

time: Thu Jul 28 17:12:54 2011

elapsed time: 0 seconds

JVM 이 java 어플리케이션에서 unexpected error (e.g. out of memory error) 를 발견했을때는 에러파일내용이 아래와 같이 나오기도 한다.(헤더부분만 첨부함)

#

# An unexpected error has been detected by Java Runtime Environment:

#

# java.lang.OutOfMemoryError: requested 32756 bytes for ChunkPool::allocate. Out of swap space?

#

#  Internal Error (allocation.cpp:120), pid=14963, tid=2411264912

#  Error: ChunkPool::allocate

#

# Java VM: OpenJDK Server VM (1.6.0-b09 mixed mode linux-x86)

# If you would like to submit a bug report, please visit:

#   http://icedtea.classpath.org/bugzilla

#

 
참조
http://www.java.com/en/download/help/error_hotspot.xml 
http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html#DebuggingOptions 

http://forums.oracle.com/forums/thread.jspa?threadID=1237584 (-XX:OnError 옵션을 이용해 에러파일 내용을 메일로 보내는 예제까지)