2018.05.30
Thread Dump
目次
- 1. Thread
- 2.Thread Dump実行
- 3. Thread Dumpファイル
- 4. Thread Dump分析例
- 5. Thread DumpとGC Dump
- 6. Thread DumpとJConsole
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を参照してください。