Thread Dump

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状態

 

JDK1.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がどのような操作を行う時に競合が発生したか分析する必要があります。

 

注意

 

現在実行中の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  (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  (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  (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  (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  (a java.lang.ref.ReferenceQueue$Lock)
       at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
       - locked  (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  (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  (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 .
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: 
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: 
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): 
2LKREGMON          JITC MB UPDATE lock (0x350F7358): 
2LKREGMON          JITC Global_Compile lock (0x350F72A8): 
2LKREGMON          Integer lock access-lock (0x3488F008): 
2LKREGMON          Free Class Loader Cache Entry lock (0x3003FA08): 
2LKREGMON          IO lock (0x3003F958): 
...
2LKREGMON          JIT General subpool lock (0x3003E9C8): 
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) {  
                //synchronized(dump_test.lock) {   
                //

 

次の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  (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  (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  (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  (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に1つの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

 

JDK1.5から基本的に提供するJConsoleはJMXとPlatform MBeanを利用してJVMの状態を監視する機能を提供します。PlatformMBeanの中ThreadMXBeanを利用すれば、Thread Dumpが提供する情報と同じレベルのThread情報をJava APIやJConsole UIを介して取得することができます。JConsoleの詳細については、JConsole Guideを参照してください。PlatformMBeanを使用する方法については、java.lang.management Packageを参照してください。