over 3 years ago

Thread dump作為分析程式是一個非常有用的手段。當你覺得程式hang住不動、CPU使用率過高或是performance衝不高時,且無法使用jconsole/VisualVM等圖形介面的工具時,透過Thread dump可將JVM裡當下所有的Thread資訊產生text file,幫助我們分析程式是不是thread有dead lock的現象。

產生Thread dump text file

為了產生Thread dump,首先要找出要觀察分析的process id。在Linux可以使用ps aux指令或是使用JDK所提供的jps工具。

$ jps -l
2008 sun.tools.jps.Jps
1999 com.terry.Test

假設要分析com.terry.Main此process裡的thread情況,也就是將其thread的資訊產生出來。在Linux可以使用kill -3 pid或是使用JDK工具jstack pid。執行完後會將結果會顯示在standard console,當然更常用的是將結果導至指定的file。(example: jstack 1999 > thread.dump)

$ jstack 1999
2014-06-02 14:39:07
Full thread dump Java HotSpot(TM) Client VM (25.5-b02 mixed mode):

"Attach Listener" #7 daemon prio=9 os_prio=0 tid=0xb6994800 nid=0x7ea runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #6 daemon prio=9 os_prio=0 tid=0xb6983800 nid=0x7d6 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0xb6980000 nid=0x7d5 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0xb697ec00 nid=0x7d4 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0xb6960c00 nid=0x7d3 in Object.wait() [0xa435c000]
   java.lang.Thread.State: WAITING (on object monitor)
  at java.lang.Object.wait(Native Method)
  - waiting on <0xa4a056d0> (a java.lang.ref.ReferenceQueue$Lock)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
  - locked <0xa4a056d0> (a java.lang.ref.ReferenceQueue$Lock)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
  at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0xb695e400 nid=0x7d2 in Object.wait() [0xb4670000]
   java.lang.Thread.State: WAITING (on object monitor)
  at java.lang.Object.wait(Native Method)
  - waiting on <0xa4a051f8> (a java.lang.ref.Reference$Lock)
  at java.lang.Object.wait(Object.java:502)
  at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
  - locked <0xa4a051f8> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0xb6907000 nid=0x7d0 runnable [0xb6a58000]
   java.lang.Thread.State: RUNNABLE
  at com.terry.Test.main(Test.java:5)

"VM Thread" os_prio=0 tid=0xb695b400 nid=0x7d1 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0xb6985800 nid=0x7d7 waiting on condition 

JNI global references: 7

如果你的程式是在Tomcat,JBoss的Application Server上跑,dump出來的資料會多出Heap memory的訊息在最後,如以下:

2014-06-02 14:39:07
Full thread dump Java HotSpot(TM) Client VM (25.5-b02 mixed mode):
......(略)
Heap
 def new generation   total 7360K, used 6454K [0xa4c00000, 0xa53f0000, 0xaa000000)
  eden space 6592K,  86% used [0xa4c00000, 0xa518d900, 0xa5270000)
  from space 768K, 100% used [0xa5270000, 0xa5330000, 0xa5330000)
  to   space 768K,   0% used [0xa5330000, 0xa5330000, 0xa53f0000)
 tenured generation   total 16200K, used 11009K [0xaa000000, 0xaafd2000, 0xb4800000)
   the space 16200K,  67% used [0xaa000000, 0xaaac0708, 0xaaac0800, 0xaafd2000)
 Metaspace       used 8732K, capacity 8807K, committed 8856K, reserved 9520K

PS:jstack在JDK1.5之後開始提供此功能,且在1.5版本jstack為實驗性工具,且有所限制。Reference:Jstack - Oracle Software Downloads

NOTE – This utility is unsupported and may or may not be available in future versions of the J2SE SDK. jstack is not currently available on Windows platforms or on the Linux Itanium platform.

我個人工作上,之前有維護過用JDK1.4開發的專案軟體,在此情況下就只能用kill -3 pid的方式來產生Thread dump。

Thread dump格式內容

JVM資訊

2014-06-02 14:39:07
Full thread dump Java HotSpot(TM) Client VM (25.5-b02 mixed mode):

首先會看到的是指出你所dump的時間點,接著是JVM的資訊。而不同的JVM(HotSpot,JRockit…etc)及不同的JDK版本輸出的格式略有所不同。

Thread資訊

"main" #1 prio=5 os_prio=0 tid=0xb6907000 nid=0x7d0 runnable [0xb6a58000]
   java.lang.Thread.State: RUNNABLE
  at com.terry.Test.main(Test.java:5)

在troubleshooting時,基本上會使用到這些資訊

  • thread name,在分析的時候可以知道此thread是被誰產生出來的。此例為"main"
  • tid 也就是thread id
  • java.lang.Thread.State thread dump時該thread當時的state
  • Stack Trace 接著state的後面,表示thread dump時該thread當時執行到何處

範例分析

CPU使用率過高

Java執行當中發現CPU的使用率高居不下時,就可以透過Thread dump來幫助我們到底是那一個Thread佔用了CPU。首先第一步要找出的是thread id,跟據OS的不同,方式也有所不同。

取得Thread id

Linux使用top -H指令,結果如下

$ top -H

top - 14:42:27 up 8 min,  3 users,  load average: 1.74, 1.62, 0.95
Threads: 285 total,   2 running, 283 sleeping,   0 stopped,   0 zombie
%Cpu(s): 74.7 us, 25.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   1026332 total,   544096 used,   482236 free,    69888 buffers
KiB Swap:  1045500 total,        0 used,  1045500 free,   310996 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 2000 febain    20   0  313m  11m 6216 R  73.5  1.1   3:07.47 java
 1354 root      20   0  162m  23m 9996 S  10.6  2.3   0:48.63 Xorg
 1684 febain    20   0  531m  55m  26m S   6.3  5.5   0:22.28 Sync
 1673 febain    20   0  531m  55m  26m S   3.4  5.5   0:16.46 cinnamon
 2030 febain    20   0  5352 1476 1020 R   1.9  0.1   0:00.76 top
 1484 febain    20   0  9756 1432  964 S   1.6  0.1   0:06.47 X11-NOTIFY
 1841 febain    20   0  178m  16m  11m S   0.6  1.6   0:05.14 gnome-terminal
 2007 febain    20   0  313m  11m 6216 S   0.6  1.1   0:01.65 java
    9 root      20   0     0    0    0 S   0.3  0.0   0:07.36 rcu_sched
   23 root      20   0     0    0    0 S   0.3  0.0   0:01.61 kworker/0:1
    1 root      20   0  3916 2304 1380 S   0.0  0.2   0:11.70 init
    2 root      20   0     0    0    0 S   0.0  0.0   0:00.03 kthreadd
    3 root      20   0     0    0    0 S   0.0  0.0   0:00.99 ksoftirqd/0
    5 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 kworker/0:0H
    7 root      rt   0     0    0    0 S   0.0  0.0   0:00.01 migration/0
    8 root      20   0     0    0    0 S   0.0  0.0   0:00.00 rcu_bh
   10 root      rt   0     0    0    0 S   0.0  0.0   0:00.08 watchdog/0
   11 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 khelper
   12 root      20   0     0    0    0 S   0.0  0.0   0:00.02 kdevtmpfs
   13 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 netns

Solaris則是使用prstat -L pid,例如:

$ jps -l
2008 sun.tools.jps.Jps
1999 com.terry.Test
$ prstat -L 1999

將Thread id轉換成16進制

在上面top -H的結果就有兩個java的thread(2000,2007)。可以看到的是PID=2000 thread使用率達73.5%,所以想查詢此thread的資訊,但在OS上顯示是thread id會是十進制,而在thread dump裡所記錄的tid卻是16進制。故要先做轉換,將pid 2000的值轉為7d0,也就能找到nid=0x7d0 main這個thread,發現它目前執行到Test的第五行,且為無限迴圈。

其他範例分析

請看此篇How to Analyze Java Thread Dumps中的Thread Dump Patterns by Type部份

Thread dump viewer tool

有時候為了找出在不同時間內的thread的處理情況,來檢查出thread是否有deadlock時,會產出多個的thread dump file。這時可以透過tool來幫助分析。

我所使用的是圖形介面的工具-Samurai,使用的方式很簡單。從Samurai web site下載jar後,執行java -jar samurai.jar。再將你要分析的thread dump file拖拉至視窗或是從功能表列的File/open開啟,Samurai就會進行parse,如下圖。

← Apache Thrift - (1)安裝 vim-airline - 狀態列顯示的好幫手 →
 
comments powered by Disqus