|
Thread Dump
EXEM Knowledge Base
목차[숨기기] |
[편집] Thread
[편집] Java와 Thread
Java Application은 기본적으로 Thread에 의해 움직인다.
- VM Background Thread: Compile, Optimization, Garbage Collection 등 JVM 내부의 일을 수행하는 Background Thread들이다.
- Main Thread: main(String[] args) 메소드를 실행하는 Thread. 사용자가 명시적으로 Thread를 수행하지 않더라도 JVM은 하나의 Main Thread를 생성해서 Application을 구동한다. Sun HotSpot JVM에서는 VM Thread라는 이름이 부여된다.
- User Thread: 사용자에 의해 명시적으로 생성된 Thread들이다. java.lang.Thread를 상속(extends)받거나, java.lang.Runnable 인터페이스를 구현(implements)함으로써 User Thread를 생성할 수 있다.
Web Application과 같이 많은 수의 동시 사용자들을 처리하는 Applicaiton들은 수십 개 ~ 수백 개의 Thread를 사용한다. 이러한 Application들에서는 Thread간의 경합(Contention)과 Deadlock이 발생할 위험이 상존한다. Thread 경합에 의한 성능 저하 현상이 발생할 경우에는 Thread들이 어떤 상태에 있는지를 정확하게 파악해야 한다.
Thread간의 경합을 관찰할 수 있는 가장 좋은 방법은 Thread Dump를 이용하는 것이다. Thread Dump의 결과를 이용하면 Thread의 현재 활동 상황을 한눈에 파악할 수 있다.
[편집] Thread 동기화
각 Thread는 다른 Thread와 독립적으로 동시에 실행가능하다. 따라서 동시에 여러 개의 Thread가 동일 자원을 사용하게 되면 데이터의 정합성이 보장되지 않는다. 이런 경우에는 Thread 동기화를 통해 한번에 하나의 Thread만이 자원을 사용하도록 보장해야 한다.
Java에서는 Monitor를 통해 Thread 동기화를 수행한다. 각 Object는 하나의 Monitor를 가지고 있다. 한번에 단 하나의 Thread만이 Monitor를 소유할 수 있으며, 그동안 다른 Thread 들은 Wait Queue에 대기해야 한다.
[편집] Thread 상태
JDK 1.5부터는 java.lang.Thread.State Class를 통해 Thread의 상태 정보를 제공한다. Thread.State가 제공하는 Thread 상태 정보는 다음과 같다.
- NEW: Thread가 생성되었지만 아직 실행은 안된 상태
- RUNNABLE: 현재 CPU를 점유하고 작업을 수행 중인 상태
- BLOCKED: Monitor 경합에 의해 Blocking된 상태
- WAITING: Object.wait 메소드를 호출하고 대기하고 있는 상태
- TIMED_WAITING: Object.wait(timeout) 메소드를 호출하고 대기하고 있는 상태
- TERMINATED: 작업을 끝낸 상태
Thread 경합이 발생하는 경우 BLOCKED나 WATIING 상태의 Thread들이 증가한다. Thread Dump를 통해 Thread들이 어떤 작업을 수행 중에 경합이 발생했는지 분석해야 한다.
[편집] Thread Dump 수행
현재 수행 중인 Java Application에 대해 Thread Dump를 수행하는 방법은 다음과 같다.
- Unix/Linux
- Ctrl+\
- kill 명령: kill -3 [PID_of_Java Process] 명령을 수행한다.
- Windows
- Ctrl+Break
- 만일 Java Application이 Windows Service의 형태로 작동 중이라면 Ctrl+Break 키를 보낼 수 없다. 이런 경우에는 SendSignal을 이용해서 원하는 프로세스에 Signal(Ctrl+Break) 을 보낼 수 있다.
[편집] Thread Dump 파일
[편집] Thread Dump 파일 위치
- Sun Hotspot JVM에서는 Java Application이 실행된 표준 Console(stdout이나 stderr)에 결과가 출력된다. 따라서 Redirection을 통해 결과를 저장하도록 하는 것이 좋다.
- IBM JVM에서는 Java Application이 실행된 디렉토리에 javacore_xxxx와 같은 형태의 Text File로 결과가 저장된다.
[편집] Thread Dump 파일 형식과 내용
Thread Dump 파일의 형식과 내용은 JVM의 종류마다 조금씩 다르다.
[편집] Sun HotSpot JVM (1.5 기준)
Sun HotSpot JVM는 JVM 내에서 생성된 Thread들과 Stack Trace, Lock 정보 등 가장 기본적인 정보들을 보여준다.
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_04-b05 mixed mode): "DestroyJavaVM" prio=1 tid=0x0000000040115580 nid=0x1e18 waiting on condition [0x0000000000000000..0x0000007fbfffd380] "Thread-3" prio=1 tid=0x0000002afedbd330 nid=0x1e27 waiting for monitor entry [0x00000000410c9000..0x00000000410c9bb0] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-2" prio=1 tid=0x0000002afeda6900 nid=0x1e26 waiting for monitor entry [0x0000000040fc8000..0x0000000040fc8c30] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-1" prio=1 tid=0x0000002afeda5fe0 nid=0x1e25 waiting for monitor entry [0x0000000040ec7000..0x0000000040ec7cb0] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-0" prio=1 tid=0x0000002afeda3520 nid=0x1e24 runnable [0x0000000040dc6000..0x0000000040dc6d30] at Thread2.run(dump_test.java:38) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Low Memory Detector" daemon prio=1 tid=0x0000002afed9b8b0 nid=0x1e22 runnable [0x0000000000000000..0x0000000000000000] "CompilerThread1" daemon prio=1 tid=0x0000002afed99cb0 nid=0x1e21 waiting on condition [0x0000000000000000..0x0000000040ac2790] "CompilerThread0" daemon prio=1 tid=0x0000002afed98730 nid=0x1e20 waiting on condition [0x0000000000000000..0x00000000409c1410] "AdapterThread" daemon prio=1 tid=0x0000002afed97000 nid=0x1e1f waiting on condition [0x0000000000000000..0x0000000000000000] "Signal Dispatcher" daemon prio=1 tid=0x0000002afed95cd0 nid=0x1e1e waiting on condition [0x0000000000000000..0x0000000000000000] "Finalizer" daemon prio=1 tid=0x0000002afed81d00 nid=0x1e1d in Object.wait() [0x00000000406bf000..0x00000000406bfcb0] at java.lang.Object.wait(Native Method) - waiting on <0x0000002af43f0d60> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x0000002af43f0d60> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=1 tid=0x0000002afed80f20 nid=0x1e1c in Object.wait() [0x00000000405be000..0x00000000405bed30] at java.lang.Object.wait(Native Method) - waiting on <0x0000002af43f0be0> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:474) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x0000002af43f0be0> (a java.lang.ref.Reference$Lock) "VM Thread" prio=1 tid=0x00000000401ba4c0 nid=0x1e1b runnable "GC task thread#0 (ParallelGC)" prio=1 tid=0x00000000401a7f50 nid=0x1e19 runnable "GC task thread#1 (ParallelGC)" prio=1 tid=0x00000000401a85f0 nid=0x1e1a runnable "VM Periodic Task Thread" prio=1 tid=0x0000002afed9d4d0 nid=0x1e23 waiting on condition
[편집] IBM JVM (1.5 기준)
IBM JVM의 Thread Dump는 Sun HotSpot JVM에 비해 훨씬 다양한 정보를 제공한다. JVM의 환경 정보, Singal Handler 정보, Lock 정보, C Stack Trace를 포함한 완전한 형태의 Stack Trace, Class 정보 등이 제공된다. IBM JVM에서는 Thread Dump라는 용어 보다는 Java Core라는 용어가 더 많이 사용된다.
NULL ------------------------------------------------------------------------ 0SECTION TITLE subcomponent dump routine NULL =============================== 1TISIGINFO signal 3 received 1TIDATETIME Date: 2007/08/24 at 10:06:46 1TIFILENAME Javacore filename: /home/oracle/javacore2113620.1187914006.txt NULL ------------------------------------------------------------------------ 0SECTION XHPI subcomponent dump routine NULL ============================== 1XHTIME Fri Aug 24 10:06:46 2007 1XHSIGRECV SIGQUIT received at 0x0 in <unknown>. 1XHFULLVERSION J2RE 1.4.2 IBM AIX build ca142-20050929a (SR3) NULL 1XHCURRENTTHD Current Thread Details NULL ---------------------- 2XHCURRSYSTHD "Signal dispatcher" sys_thread_t:0x346340A0 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINEERR unavailable - stack address not valid 1XHOPENV Operating Environment NULL --------------------- 2XHHOSTNAME Host : oag1:210.122.227.251 2XHOSLEVEL OS Level : AIX 5.3.0.0 2XHCPUS Processors - 3XHCPUARCH Architecture : POWER_PC (impl: unknown, ver: unknown) 3XHNUMCPUS How Many : 2 3XHCPUSENABLED Enabled : 2 NULL 1XHUSERLIMITS User Limits (in bytes except for NOFILE and NPROC) - NULL ----------- 2XHUSERLIMIT RLIMIT_FSIZE : infinity 2XHUSERLIMIT RLIMIT_DATA : 2147483645 2XHUSERLIMIT RLIMIT_STACK : 2147483646 2XHUSERLIMIT RLIMIT_CORE : infinity 2XHUSERLIMIT RLIMIT_NOFILE : 2000 2XHLIMIT NPROC(max) : 2048 NULL 1XHPAGESPACES Page Space (in blocks) - NULL ---------- 2XHPAGESPACE /dev/hd6: size=2097152, free=1642282 NULL 1XHSIGHANDLERS JVM Signal Handlers NULL ------------------- 2XHSIGHANDLER SIGHUP : intrDispatchMD (libhpi.a) 2XHSIGHANDLER SIGINT : intrDispatchMD (libhpi.a) 2XHSIGHANDLER SIGQUIT : intrDispatchMD (libhpi.a) 2XHSIGHANDLER SIGILL : intrDispatchMD (libhpi.a) 2XHSIGHANDLER SIGTRAP : JITSigTrapHandler (libjitc.a) ... NULL 1XHSIGHANDLERS Chained Signal Handlers NULL ----------------------- 2XHSIGHANDLER SIGHUP : intrDispatchMD (libhpi.a) 2XHSIGHANDLER SIGINT : intrDispatchMD (libhpi.a) ... 2XHSIGHANDLER SIGTERM : intrDispatchMD (libhpi.a) NULL 1XHENVVARS Environment Variables NULL --------------------- 2XHENVVAR _=/usr/java14/jre/bin/java 2XHENVVAR TMPDIR=/tmp 2XHENVVAR LANG=C 2XHENVVAR TEMP=/tmp 2XHENVVAR LOGIN=oracle 2XHENVVAR G_BROKEN_FILENAMES=1 2XHENVVAR PATH=/oracle/crs10gR2/bin:/oracle/db10gR2/bin:/usr/bin:/etc:/usr/sbin:/usr/ucb:/usr/bin/X11:/sbin:/usr/java14/jre/bin:/usr/java14/bin:.:/usr/es/sbin/cluster:/usr/es/sbin/cluster/utilities:/usr/es/sbin/cluster/sbin:/usr/es/sbin/cluster/diag 2XHENVVAR ORACLE_BASE=/oracle ... LD_LIBRARY_PATH=/oracle/crs10gR2/lib:/oracle/crs10gR2/lib32:/oracle/db10gR2/lib:/oracle/db10gR2/lib32: 2XHENVVAR NLSPATH=/usr/lib/nls/msg/%L/%N:/usr/lib/nls/msg/%L/%N.cat 2XHENVVAR _IBM_ENV_INITIAL_2113620=805345784 2XHENVVAR IBM_JAVA_COMMAND_LINE=java -cp . dump_test NULL 1XHLOADEDLIBS Loaded Libraries (sizes in bytes) NULL --------------------------------- 2XHLIBNAME /usr/java14/jre/bin/libjitc.a 3XHLIBSIZE filesize : 2813389 3XHLIBSTART text start : 0xDBA79000 3XHLIBLDSIZE text size : 0x23EA87 3XHLIBLDORG data start : 0xF29817D8 3XHLIBLDDATASZ data size : 0x1A944 ... 2XHLIBNAME /usr/lib/libc.a 3XHLIBSIZE filesize : 8179014 3XHLIBSTART text start : 0xD02EBDA0 3XHLIBLDSIZE text size : 0x249EAB 3XHLIBLDORG data start : 0xF10206A8 3XHLIBLDDATASZ data size : 0x9BE30 NULL NULL ------------------------------------------------------------------------ 0SECTION CI subcomponent dump routine NULL ============================ 1CIJAVAVERSION J2RE 1.4.2 IBM AIX build ca142-20050929a (SR3) 1CIRUNNINGAS Running as a standalone JVM 1CICMDLINE java -cp . dump_test 1CIJAVAHOMEDIR Java Home Dir: /usr/java14/jre 1CIJAVADLLDIR Java DLL Dir: /usr/java14/jre/bin 1CISYSCP Sys Classpath: /usr/java14/jre/lib/core.jar:/usr/java14/jre/lib/graphics.jar:/usr/java14/jre/lib/security.jar:/usr/java14/jre/lib/server.jar:/usr/java14/jre/lib/xml.jar:/usr/java14/jre/lib/charsets.jar:/usr/java14/jre/classes:/usr/java14/jre/lib/ibmcertpathprovider.jar:/usr/java14/jre/lib/ibmjaaslm.jar:/usr/java14/jre/lib/ibmjcefw.jar:/usr/java14/jre/lib/ibmjgssprovider.jar:/usr/java14/jre/lib/ibmjssefips.jar:/usr/java14/jre/lib/ibmjsseprovider.jar:/usr/java14/jre/lib/ibmorb.jar:/usr/java14/jre/lib/ibmorbapi.jar:/usr/java14/jre/lib/ibmpkcs.jar 1CIUSERARGS UserArgs: 2CIUSERARG vfprintf 0x30001034 2CIUSERARG -Dinvokedviajava 2CIUSERARG -Djava.class.path=. 2CIUSERARG vfprintf NULL 1CIJVMMI JVM Monitoring Interface (JVMMI) NULL ------------------------ 2CIJVMMIOFF No events are enabled. NULL NULL ------------------------------------------------------------------------ 0SECTION DC subcomponent dump routine NULL ============================ 1DCHEADEREYE Header eye catcher DCST 1DCHEADERLEN Header length 24 1DCHEADERVER Header version 1 1DCHEADERMOD Header modification 0 1DCINTERFACE DC Interface at 0xF294D89C with 15 entries 2DCINTERFACE 1 - dcCString2JavaString 0xF294A350 2DCINTERFACE 2 - dcInt642CString 0xF294A35C ... 2DCINTERFACE 15 - dcDumpRoutine 0xF294A3F8 1DCARRAYINFO Array info at 0xF293DD68 with 16 entries 2DCARRAYINFO 1 - index 0 signature 0 name N/A factor 0 ... 2DCARRAYINFO 16 - index 0 signature 0 name uint3[] factor 0 NULL ------------------------------------------------------------------------ 0SECTION DG subcomponent dump routine NULL ============================ 1DGTRCENABLED Trace enabled: Yes 2DGTRCTYPE Trace: Internal 2DGTRCBUFFERS Buffer specification: 8k 2DGTRCBUFALLOC Buffers allocated: 0 2DGTRCBUFUSED Buffers in use: 0 1DGJDUMPBUFF Javadump buffer size (allocated): 2621440 NULL ------------------------------------------------------------------------ 0SECTION ST subcomponent dump routine NULL ============================ 1STGCMODES Resettable GC: No 1STGCMODES Concurrent GC: No 1STCURHBASE Current Heap Base: 0x300601FC 1STCURHLIM Current Heap Limit: 0x3045FBFC 1STMWHBASE Middleware Heap Base: 0x300601FC 1STMWHLIM Middleware Heap Limit: 0x3045FBFC 1STGCHELPERS Number of GC Helper Threads: 1 1STJVMOPTS -Xconcurrentlevel: 0 1STJVMOPTS -Xconcurrentbackground: 0 1STGCCTR GC Counter: 0 1STAFCTR AF Counter: 0 1STHEAPFREE Bytes of Heap Space Free: 3267e8 1STHEAPALLOC Bytes of Heap Space Allocated: 3ffa00 1STSMBASE SM Base: 0x0 1STSMEND SM End: 0x0 1STPAMSTART PAM Start: 0x0 1STPAMEND PAM End: 0x0 1STCOMACTION Compact Action: 0 NULL ------------------------------------------------------------------------ 0SECTION XE subcomponent dump routine NULL ============================ 1XETHRESHOLD MMI threshold for java methods is set to 1250 1XEJITINIT JIT is initialized 1XEJVMPIOFF JVMPI is not activated 1XEJNITHRESH MMI threshold for JNI methods is set to 0 1XETRCHIS Trace history length is set to 4 1XEJITDUMP JIT dump routine is not yet implemented. NULL ------------------------------------------------------------------------ 0SECTION LK subcomponent dump routine NULL ============================ NULL 1LKPOOLINFO Monitor pool info: 2LKPOOLINIT Initial monitor count: 32 2LKPOOLEXPNUM Minimum number of free monitors before expansion: 5 2LKPOOLEXPBY Pool will next be expanded by: 16 2LKPOOLTOTAL Current total number of monitors: 32 2LKPOOLFREE Current number of free monitors: 29 NULL 1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors): 2LKMONINUSE sys_mon_t:0x3003BFF8 infl_mon_t: 0x3003BA68: 3LKMONOBJECT java.lang.ref.Reference$Lock@300E0610/300E0618: <unowned> 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "Reference Handler" (0x3463D320) 2LKMONINUSE sys_mon_t:0x3003C0A8 infl_mon_t: 0x3003BA94: 3LKMONOBJECT java.lang.ref.ReferenceQueue$Lock@300E0348/300E0350: <unowned> 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "Finalizer" (0x3474C820) 2LKMONINUSE sys_mon_t:0x3003C158 infl_mon_t: 0x00000000: 3LKMONOBJECT java.lang.Object@30127640/30127648: Flat locked by thread ident 0x08, entry count 1 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "Thread-1" (0x356716A0) 3LKWAITNOTIFY "Thread-2" (0x356F8020) 3LKWAITNOTIFY "Thread-3" (0x3577FA20) NULL 1LKREGMONDUMP JVM System Monitor Dump (registered monitors): 2LKREGMON JITC CHA lock (0x3488F0B8): <unowned> 2LKREGMON JITC MB UPDATE lock (0x350F7358): <unowned> 2LKREGMON JITC Global_Compile lock (0x350F72A8): <unowned> 2LKREGMON Integer lock access-lock (0x3488F008): <unowned> 2LKREGMON Free Class Loader Cache Entry lock (0x3003FA08): <unowned> 2LKREGMON IO lock (0x3003F958): <unowned> ... 2LKREGMON JIT General subpool lock (0x3003E9C8): <unowned> NULL 1LKFLATMONDUMP Thread identifiers (as used in flat monitors): 2LKFLATMON ident 0x02 "Thread-4" (0x3000D2A0) ee 0x3000D080 2LKFLATMON ident 0x0B "Thread-3" (0x3577FA20) ee 0x3577F800 2LKFLATMON ident 0x0A "Thread-2" (0x356F8020) ee 0x356F7E00 2LKFLATMON ident 0x09 "Thread-1" (0x356716A0) ee 0x35671480 2LKFLATMON ident 0x08 "Thread-0" (0x355E71A0) ee 0x355E6F80 2LKFLATMON ident 0x05 "Finalizer" (0x3474C820) ee 0x3474C600 2LKFLATMON ident 0x04 "Reference Handler" (0x3463D320) ee 0x3463D100 2LKFLATMON ident 0x03 "Signal dispatcher" (0x346340A0) ee 0x34633E80 NULL 1LKOBJMONDUMP Java Object Monitor Dump (flat & inflated object-monitors): 2LKINFLATEDMON java.lang.ref.ReferenceQueue$Lock@300E0348/300E0350 3LKINFLDETAILS locknflags 80000200 Monitor inflated infl_mon 0x3003BA94 2LKINFLATEDMON java.lang.ref.Reference$Lock@300E0610/300E0618 3LKINFLDETAILS locknflags 80000100 Monitor inflated infl_mon 0x3003BA68 2LKFLATLOCKED java.lang.Object@30127640/30127648 3LKFLATDETAILS locknflags 00080000 Flat locked by thread ident 0x08, entry count 1 NULL ------------------------------------------------------------------------ 0SECTION XM subcomponent dump routine NULL ============================ NULL 1XMCURTHDINFO Current Thread Details NULL ---------------------- 3XMTHREADINFO "Signal dispatcher" (TID:0x300CB960, sys_thread_t:0x346340A0, state:R, native ID:0x102) prio=5 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINEERR unavailable - stack address not valid 1XMTHDINFO All Thread Details NULL ------------------ NULL 2XMFULLTHDDUMP Full thread dump Classic VM (J2RE 1.4.2 IBM AIX build ca142-20050929a (SR3), native threads): 3XMTHREADINFO "Thread-4" (TID:0x300CB530, sys_thread_t:0x3000D2A0, state:CW, native ID:0x1) prio=5 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINE at 0xDB84E184 in xeRunJavaVarArgMethod 3XHSTACKLINE at 0xD0121A94 in _event_wait 3XHSTACKLINE at 0xD012BBB0 in _cond_wait_local 3XHSTACKLINE at 0xD012C06C in _cond_wait 3XHSTACKLINE at 0xD012CBE4 in pthread_cond_wait 3XHSTACKLINE at 0xDBA18DD0 in condvarWait 3XHSTACKLINE at 0xDBA17AA0 in sysMonitorWait 3XHSTACKLINE at 0xDB8CEEF0 in xmWaitForSingleThreaded 3XHSTACKLINE at 0xDB81F69C in jni_DestroyJavaVM 3XMTHREADINFO "Thread-3" (TID:0x300CB588, sys_thread_t:0x3577FA20, state:CW, native ID:0xA0B) prio=5 4XESTACKTRACE at Thread1.run(dump_test.java:21) 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINE at 0xD0121A94 in _event_wait 3XHSTACKLINE at 0xD012BBB0 in _cond_wait_local 3XHSTACKLINE at 0xD012C06C in _cond_wait 3XHSTACKLINE at 0xD012C9B8 in pthread_cond_timedwait 3XHSTACKLINE at 0xDBA18B28 in condvarTimedWaitUpTo248Days 3XHSTACKLINE at 0xDBA18CB8 in condvarTimedWait 3XHSTACKLINE at 0xDBA17AA0 in sysMonitorWait 3XHSTACKLINE at 0xDB8CB304 in lkMonitorEnter 3XHSTACKLINE at 0xDB856558 in mmipExecuteJava 3XHSTACKLINE at 0xDB84E184 in xeRunJavaVarArgMethod 3XHSTACKLINE at 0xDB84E418 in xeRunDynamicMethod 3XHSTACKLINE at 0xDB83B524 in threadRT0 3XHSTACKLINE at 0xDB8CE61C in xmExecuteThread 3XHSTACKLINE at 0xDB8D2A7C in threadStart 3XHSTACKLINE at 0xDBA10E50 in _start 3XHSTACKLINE at 0xD011147C in _pthread_body 3XHSTACKLINE at 0xD011147C in _pthread_body 3XMTHREADINFO "Thread-2" (TID:0x300CB5E8, sys_thread_t:0x356F8020, state:CW, native ID:0x90A) prio=5 4XESTACKTRACE at Thread1.run(dump_test.java:21) 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINE at 0xD0121A94 in _event_wait 3XHSTACKLINE at 0xD012BBB0 in _cond_wait_local 3XHSTACKLINE at 0xD012C06C in _cond_wait ... 3XHSTACKLINE at 0xD011147C in _pthread_body 3XHSTACKLINE at 0xD011147C in _pthread_body 3XMTHREADINFO "Thread-0" (TID:0x300CB6A8, sys_thread_t:0x355E71A0, state:R, native ID:0x708) prio=5 4XESTACKTRACE at Thread2.run(dump_test.java(Compiled Code)) 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINE at 0x344DE720 in 3XMTHREADINFO "Finalizer" (TID:0x300CB8B0, sys_thread_t:0x3474C820, state:CW, native ID:0x304) prio=8 4XESTACKTRACE at java.lang.Object.wait(Native Method) 4XESTACKTRACE at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144) 4XESTACKTRACE at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:160) ... 3XHSTACKLINE at 0xDBA10E50 in _start 3XHSTACKLINE at 0xD011147C in _pthread_body 3XHSTACKLINE at 0xD011147C in _pthread_body 3XMTHREADINFO "Reference Handler" (TID:0x300CB908, sys_thread_t:0x3463D320, state:CW, native ID:0x203) prio=10 4XESTACKTRACE at java.lang.ref.Reference.process(Native Method) 4XESTACKTRACE at java.lang.ref.Reference.access$300(Reference.java:50) 4XESTACKTRACE at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:130) 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINE at 0xDBA5D928 in 3XHSTACKLINE at 0xD0121A94 in _event_wait ... 3XHSTACKLINE at 0xDBA10E50 in _start 3XHSTACKLINE at 0xD011147C in _pthread_body 3XHSTACKLINE at 0xD011147C in _pthread_body 3XMTHREADINFO "Signal dispatcher" (TID:0x300CB960, sys_thread_t:0x346340A0, state:R, native ID:0x102) prio=5 3XHNATIVESTACK Native Stack NULL ------------ 3XHSTACKLINEERR unavailable - stack address not valid NULL ------------------------------------------------------------------------ 0SECTION CL subcomponent dump routine NULL ============================ 1CLCLASSPATH Classpath Z(/usr/java14/jre/lib/core.jar),Z(/usr/java14/jre/lib/graphics.jar),Z(/usr/java14/jre/lib/security.jar),Z(/usr/java14/jre/lib/server.jar),Z(/usr/java14/jre/lib/xml.jar),Z(/usr/java14/jre/lib/charsets.jar),Z(/usr/java14/jre/lib/ibmcertpathprovider.jar),Z(/usr/java14/jre/lib/ibmjaaslm.jar),Z(/usr/java14/jre/lib/ibmjcefw.jar),Z(/usr/java14/jre/lib/ibmjgssprovider.jar),Z(/usr/java14/jre/lib/ibmjssefips.jar),Z(/usr/java14/jre/lib/ibmjsseprovider.jar),Z(/usr/java14/jre/lib/ibmorb.jar),Z(/usr/java14/jre/lib/ibmorbapi.jar),Z(/usr/java14/jre/lib/ibmpkcs.jar) 1CLFLAGOLDJAVA Oldjava mode false 1CLFLAGBOOTSTRP Bootstrapping false 1CLFLAGVERBOSE Verbose class dependencies false 1CLENUMVERIFY Class verification VERIFY_REMOTE 1CLPNTRNAMECLLO Namespace to classloader 0x00000000 1CLPNTRCHAINLO Start of cache entry pool 0x355B0258 1CLPNTRCHFREE Start of free cache entries 0x355B0944 1CLPNTRMETHODTB Location of method table 0x34567AE0 1CLPNTRANCHRGLN Global namespace anchor 0x30033764 1CLPNTRCLSLOADS System classloader shadow 0x34512D88 1CLPNTRSYSLOADS Classloader shadows 0x348EC748 1CLPNTRCLSEXT Extension loader 0x300CB7D8 1CLPNTRSYSLOADR System classloader 0x300CB758 1CLTEXTCLLOS Classloader summaries 1CLTEXTCLLSS 12345678: 1=primordial,2=extension,3=shareable,4=middleware,5=system,6=trusted,7=application,8=delegating 2CLTEXTCLLOADER -----ta- Loader sun/misc/Launcher$AppClassLoader(0x348EC748), Shadow 0x300CB758, Parent sun/misc/Launcher$ExtClassLoader(0x300CB7D8) 3CLNMBRLOADEDCL Number of loaded classes 3 3CLNMBRCACHECLS Number of cached classes 248 3CLHEXDALLOCTIO Allocation used for loaded classes 1 3CLHEXDPCKGEOWN Package owner 0x300CB758 2CLTEXTCLLOADER -xh-st-- Loader sun/misc/Launcher$ExtClassLoader(0x348E10E8), Shadow 0x300CB7D8, Parent *none*(0x00000000) 3CLNMBRLOADEDCL Number of loaded classes 0 3CLNMBRCACHECLS Number of cached classes 0 3CLHEXDALLOCTIO Allocation used for loaded classes 3 3CLHEXDPCKGEOWN Package owner 0x300CB7D8 2CLTEXTCLLOADER p-h-st-- Loader *System*(0x34512D88), Shadow 0x00000000 3CLNMBRLOADEDCL Number of loaded classes 290 3CLNMBRCACHECLS Number of cached classes 290 3CLHEXDALLOCTIO Allocation used for loaded classes 3 3CLHEXDPCKGEOWN Package owner 0x00000000 1CLTEXTCLLOD ClassLoader loaded classes 2CLTEXTCLLOAD Loader sun/misc/Launcher$AppClassLoader(0x348EC748) 3CLTEXTCLASS dump_test(0x300BF0E0) 3CLTEXTCLASS Thread1(0x300BEE80) 3CLTEXTCLASS Thread2(0x300BEFB0) 2CLTEXTCLLOAD Loader sun/misc/Launcher$ExtClassLoader(0x348E10E8) 2CLTEXTCLLOAD Loader *System*(0x34512D88) 3CLTEXTCLASS sun/misc/ExtensionDependency(0x348C4298) ... 3CLTEXTCLASS java/lang/LinkageError(0x34063A48) NULL ------------------------------------------------------------------------ 0SECTION Javadump End section 1DGJDUMP Javadump Buffer Usage Information NULL ================================= 2DGJDUMPALLOC Javadump buffer size (allocated): 2621440 2DGJDUMPUSED Javadump buffer size (used) : 51051 NULL ---------------------- END OF DUMP -------------------------------------
[편집] JRockit JVM (1.5 기준)
JRockit JVM이 제공하는 Thread Dump 정보는 Sun HotSpot JVM과 거의 동일하다. Thread Blocking이 발생한 경우 Thread간의 상호 관계(Chain)를 보다 시각적으로 제공한다는 장점이 있다.
===== FULL THREAD DUMP =============== Sun Aug 26 01:10:42 2007 BEA JRockit(R) R26.4.0-63_CR302700-72606-1.5.0_06-20061127-1108-win-ia32 "Thread-4" id=13 idx=0x2 tid=3212 prio=5 alive, in native, daemon "(Signal Handler)" id=2 idx=0x4 tid=3468 prio=5 alive, in native, daemon "(Code Generation Thread 1)" id=3 idx=0x6 tid=3500 prio=5 alive, in native, native_waiting, daemon "(Code Optimization Thread 1)" id=4 idx=0x8 tid=3324 prio=5 alive, in native, native_waiting, daemon "(GC Main Thread)" id=5 idx=0xa tid=1812 prio=5 alive, in native, daemon "(GC Worker Thread 1)" id=? idx=0xc tid=2652 prio=5 alive, native_waiting, daemon "(GC Worker Thread 2)" id=? idx=0xe tid=3044 prio=5 alive, native_waiting, daemon "(VM Periodic Task)" id=6 idx=0x10 tid=3360 prio=10 alive, in native, native_blocked, daemon "Finalizer" id=7 idx=0x12 tid=1772 prio=8 alive, in native, native_waiting, daemon at jrockit/memory/Finalizer.getPendingFinalizee(Z)Ljava/lang/Object;(Native Method) at jrockit/memory/Finalizer.access$100(Z)Ljava/lang/Object;(Unknown Source) at jrockit/memory/Finalizer$4.run()V(Unknown Source) at java/lang/Thread.run()V(Unknown Source) at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace "Reference Handler" id=8 idx=0x14 tid=1396 prio=10 alive, in native, native_waiting, daemon at java/lang/ref/Reference.getPending()Ljava/lang/ref/Reference;(Native Method) at java/lang/ref/Reference.access$000()Ljava/lang/ref/Reference;(Unknown Source) at java/lang/ref/Reference$ReferenceHandler.run()V(Unknown Source) at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace "Thread-0" id=9 idx=0x16 tid=3488 prio=5 alive at Thread2.run()V(dump_test.java:36) ^-- Holding lock: java/lang/Object@0x1073DF58[thin lock] at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace "Thread-1" id=10 idx=0x18 tid=3264 prio=5 alive, in native, blocked -- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock] at jrockit/vm/Threads.sleep(I)V(Native Method) at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source) at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source) at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source) at Thread1.run()V(dump_test.java:21) at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace "Thread-2" id=11 idx=0x1a tid=3580 prio=5 alive, in native, blocked -- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock] at jrockit/vm/Threads.sleep(I)V(Native Method) at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source) at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source) at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source) at Thread1.run()V(dump_test.java:21) at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace "Thread-3" id=12 idx=0x1c tid=3068 prio=5 alive, in native, blocked -- Blocked trying to get lock: java/lang/Object@0x1073DF58[thin lock] at jrockit/vm/Threads.sleep(I)V(Native Method) at jrockit/vm/Locks.waitForThinRelease(Ljava/lang/Object;I)I(Unknown Source) at jrockit/vm/Locks.monitorEnterSecondStage(Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source) at jrockit/vm/Locks.monitorEnter(Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source) at Thread1.run()V(dump_test.java:21) at jrockit/vm/RNI.c2java(IIII)V(Native Method) -- end of trace Blocked lock chains =================== Chain 2: "Thread-2" id=11 idx=0x1a tid=3580 waiting for java/lang/Object@0x1073DF58 held by: "Thread-0" id=9 idx=0x16 tid=3488 in chain 1 Chain 3: "Thread-3" id=12 idx=0x1c tid=3068 waiting for java/lang/Object@0x1073DF58 held by: "Thread-0" id=9 idx=0x16 tid=3488 in chain 1 Open lock chains ================ Chain 1: "Thread-1" id=10 idx=0x18 tid=3264 waiting for java/lang/Object@0x1073DF58 held by: "Thread-0" id=9 idx=0x16 tid=3488 (active) ===== END OF THREAD DUMP ===============
[편집] Thread Dump 분석 예
[편집] Synchronized에 의한 Thread 경합 현상
아래 예제 코드는 synchronized 블록에 의한 Thread 경합 현상을 시뮬레이션한 것이다. Thread2가 dump_test.lock에 대해 Monitor를 점유하고 장시간 작업을 수행하는 동안 세 개의 Thread1이 대기하게 된다.
public class dump_test { static Object lock = new Object(); public static void main(String[] args) { new Thread2().start(); try { Thread.sleep(10); } catch(Exception ex) {} new Thread1().start(); new Thread1().start(); new Thread1().start(); } } class Thread1 extends Thread { int idx = 1; public void run() { while(true) { synchronized(dump_test.lock) { // <-- Thread1은 synchronized 블록으로 인해 Thread2의 작업이 끝나기를 기다린다. System.out.println(idx++ + " loop\n"); } } } } class Thread2 extends Thread { public void run() { while(true) { synchronized(dump_test.lock) { // <-- Thread2는 synchronized 블록을 이용해 긴(Long) 작업을 수행한다. for(int idx=0; idx<Integer.MAX_VALUE; idx++) {} } } } }
아래 Thread Dump는 Sun HotSpot VM에서 Thread dump 결과로, 다음과 같은 정보를 확인할 수 있다.
- Thread-0은 runnable 상태로 작업을 수행하고 있다.
- Thread-1, Thread-2, Thread-3은 waiting for monitor entry 상태로 대기 상태에 있다.
- Thread-0은 0x0000002af44195c8 객체에 대해 Monitor를 점유하고 있으며, 나머지 세개의 Thread는 동일 객체를 획득하기 위해 대기하고 있다.
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_04-b05 mixed mode): "DestroyJavaVM" prio=1 tid=0x0000000040115580 nid=0x1e18 waiting on condition [0x0000000000000000..0x0000007fbfffd380] "Thread-3" prio=1 tid=0x0000002afedbd330 nid=0x1e27 waiting for monitor entry [0x00000000410c9000..0x00000000410c9bb0] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-2" prio=1 tid=0x0000002afeda6900 nid=0x1e26 waiting for monitor entry [0x0000000040fc8000..0x0000000040fc8c30] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-1" prio=1 tid=0x0000002afeda5fe0 nid=0x1e25 waiting for monitor entry [0x0000000040ec7000..0x0000000040ec7cb0] at Thread1.run(dump_test.java:22) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) "Thread-0" prio=1 tid=0x0000002afeda3520 nid=0x1e24 runnable [0x0000000040dc6000..0x0000000040dc6d30] at Thread2.run(dump_test.java:38) - waiting to lock <0x0000002af44195c8> (a java.lang.Object) ...
[편집] Deadlock에 의한 Thread 경합 현상
아래 예는 IBM JVM에서 Deadlock이 발생한 경우의 Thread Dump이다.
... 1LKDEADLOCK Deadlock detected !!! NULL --------------------- NULL 2LKDEADLOCKTHR Thread "Thread-63" (0x00000001148E3B00) 3LKDEADLOCKWTR is waiting for: 4LKDEADLOCKMON sys_mon_t:0x0000000115F458E0 infl_mon_t: 0x0000000115F45930: 4LKDEADLOCKOBJ com/mysql/jdbc/ResultSet@0700000001307E30/0700000001307E48: 3LKDEADLOCKOWN which is owned by: 2LKDEADLOCKTHR Thread "webtob1-hth0(10.27.6.22:9900)-w22 [container1-35]" (0x0000000114852600) 3LKDEADLOCKWTR which is waiting for: 4LKDEADLOCKMON sys_mon_t:0x0000000115F45850 infl_mon_t: 0x0000000115F458A0: 4LKDEADLOCKOBJ com/mysql/jdbc/Connection@07000000028A8460/07000000028A8478: 3LKDEADLOCKOWN which is owned by: 2LKDEADLOCKTHR Thread "Thread-63" (0x00000001148E3B00) ... 3XMTHREADINFO "Thread-63" (TID:0x00000001148E3B00, sys_thread_t:0x00000001148BD688, state:B, native ID:0x000000000028100F) prio=5 4XESTACKTRACE at com/mysql/jdbc/ResultSet.close(ResultSet.java:736(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/Statement.realClose(Statement.java:1584(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/PreparedStatement.realClose(PreparedStatement.java:1703(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/ServerPreparedStatement.realClose(ServerPreparedStatement.java:887(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/Connection.closeAllOpenStatements(Connection.java:2126) 4XESTACKTRACE at com/mysql/jdbc/Connection.realClose(Connection.java:4422) 4XESTACKTRACE at com/mysql/jdbc/Connection.close(Connection.java:2098) 4XESTACKTRACE at DBPool/DBConnection.close(DBConnection.java:84) 4XESTACKTRACE at DBPool/DBConnectionPool.removeUsingConnection(DBConnectionPool.java:237) 4XESTACKTRACE at DBPool/ConnectionCheck.run(ConnectionCheck.java:50) ... 3XMTHREADINFO "webtob1-hth0(10.27.6.22:9900)-w22 [container1-35]" (TID:0x0000000114852600, sys_thread_t:0x000000011484DD48, state:B, native ID:0x000000000009C0C3) prio=5 4XESTACKTRACE at com/mysql/jdbc/Field.getStringFromBytes(Field.java:583(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/Field.getName(Field.java:487(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/ResultSet.buildIndexMapping(ResultSet.java:576(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/ResultSet.findColumn(ResultSet.java:926(Compiled Code)) 4XESTACKTRACE at com/mysql/jdbc/ResultSet.getString(ResultSet.java:5015(Compiled Code)) 4XESTACKTRACE at entity/MailBoxMngImpl.getNewMailCountPBox(MailBoxMngImpl.java:285(Compiled Code)) 4XESTACKTRACE at jeus_jspwork/_groupware_servlet_engine1/_MyGroup/_groupware/_jxmail/_ko/_jsp/_inc/_500_menu_5fjsp._jspService(Bytecode PC:831(Compiled Code)) 4XESTACKTRACE at jeus/servlet/jsp/HttpJspBase.service(HttpJspBase.java:53(Compiled Code)) 4XESTACKTRACE at javax/servlet/http/HttpServlet.service(HttpServlet.java:856(Compiled Code)) 4XESTACKTRACE at jeus/servlet/jsp/JspServletWrapper.executeServlet(JspServletWrapper.java:94(Compiled Code)) 4XESTACKTRACE at jeus/servlet/engine/ServletWrapper.execute(ServletWrapper.java:214(Compiled Code)) 4XESTACKTRACE at jeus/servlet/jsp/JspServletWrapper.execute(JspServletWrapper.java:140(Compiled Code)) 4XESTACKTRACE at jeus/servlet/engine/WebtobRequestProcessor.run(WebtobRequestProcessor.java:181)
위의 Dump를 분석하면 다음과 같은 결론을 얻을 수 있다.
- "Thread-63" Thread는 java.sql.Connection 객체를 close 하고자 한다.
- "webtob1-hth0(10.27.6.22:9900)-w22 [container1-35]" Thread는 java.sql.ResultSet.getString을 이용해 데이터를 Fetch하고자 한다.
- 동일한 Connection에 대해 하나의 Thread는 close하고, 다른 Thread는 사용하고자 하는 상황에서 Deadlock이발생한다.
[편집] Thread Dump와 GC Dump
Garbage Collection이 발생하는 구간에서는 모든 Application Thread가 정지(Pause)된다. 특히 Full GC 작업이 장시간(수 초 이상) 지속되는 경우 Application 입장에서는 마치 Thread Hang이 발생한 것처럼 느껴진다. 따라서 Thread Hang 현상이 발생할 때는 GC Dump 결과를 같이 비교하는 것이 바람직하다.
[편집] Thread Dump와 JConsole
Jdk 1.5부터 기본적으로 제공하는 JConsole은 JMX와 Platform MBean을 이용해서 JVM의 상태를 모니터링하는 기능을 제공한다. PlatformMBean 들 중 ThreadMXBean을 이용하면 Thread Dump가 제공하는 정보와 같은 수준의 Thread 정보를 Java API나 JConsole UI를 통해 얻을 수 있다. JConsole에 대한 자세한 정보는 JConsole Guide를 참조한다. PlatformMBean을 사용하는 방법에 대해서는 java.lang.management Package을 참조한다.