L
o
a
d
i
n
g
.
.
.

ホーム

お知らせ

製品・ソリューション

サービス

導入事例・パートナー

EXEM Academy・ブログ

会社情報

採用情報

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を参照してください。