Thread Dump

EXEM Knowledge Base

Jump to: navigation, 찾기

목차

[편집] 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-0runnable 상태로 작업을 수행하고 있다.
  • Thread-1, Thread-2, Thread-3waiting for monitor entry 상태로 대기 상태에 있다.
  • Thread-00x0000002af44195c8 객체에 대해 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를 분석하면 다음과 같은 결론을 얻을 수 있다.

  1. "Thread-63" Thread는 java.sql.Connection 객체를 close 하고자 한다.
  2. "webtob1-hth0(10.27.6.22:9900)-w22 [container1-35]" Thread는 java.sql.ResultSet.getString을 이용해 데이터를 Fetch하고자 한다.
  3. 동일한 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부터 기본적으로 제공하는 JConsoleJMXPlatform MBean을 이용해서 JVM의 상태를 모니터링하는 기능을 제공한다. PlatformMBean 들 중 ThreadMXBean을 이용하면 Thread Dump가 제공하는 정보와 같은 수준의 Thread 정보를 Java API나 JConsole UI를 통해 얻을 수 있다. JConsole에 대한 자세한 정보는 JConsole Guide를 참조한다. PlatformMBean을 사용하는 방법에 대해서는 java.lang.management Package을 참조한다.