JAVA程序分析之Thread dump

 

Thread Dump是一个非常好用的工具，当JAVA应用程序出现资源(CPU)消耗异常时，通过它可以轻松的查找到问题所在。在诊断问题时，Thread Dump包含的信息能使很好的你分析你的程序代码。几乎所有的Java虚拟机都具有thread-dump的能力，能够及时生成程序中所有线程在某一点的状态(Thread Dump)日志。虽然各Java虚拟机输出格式上略有不同，但总体包含以下信息：线程的运行状态、标识和调用堆栈；调用堆栈中包含完整类名和调用的方法。如果可能的话还有源代码的行数。

一、以下为Windows和Linux获取Thread Dump日志的方法：

1、Windows

在执行Java程序的MSDOS窗口中，按Ctrl+break键。Thread Dump日志将直接打印在窗口中。

2、Linux

# kill -3 pid （注：pid可以通过ps -efHl |grep java或top -H命令获取。)

为了反映线程状态的动态变化，需要接连多次做thread dump，每次间隔10-20s。

不同linux环境和执行Java程序的方式，输出日志的地方和方式也可能不同。在IBM的PowerPC小型机上的linux上执行kill -3 pid会在工作目录下产生类似javacore.20100409.161739.7614.0001.txt的文件。而在普通Linux机器上，则日志会输出到控制台。如：Tomcat的Thread Dump会输出到命令行控制台或者logs的catalina.out文件。nohup方式运行jar程序时，Thread Dump日志会输出到执行命令行时所在目录的nohup.out文件。

二、日志说明

 

2012-09-25 10:25:32
Full thread dump Java HotSpot(TM) Server VM (20.8-b03 mixed mode):

"DestroyJavaVM" prio=10 tid=0x8fb96000 nid=0x54d8 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Thread-4" prio=10 tid=0x8fb91800 nid=0x54e9 waiting on condition [0x8f9f6000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.nettrace.tool.udp.URLDataSender.run(URLDataSender.java:47)

"Thread-3" prio=10 tid=0x8fb6fc00 nid=0x54e8 waiting on condition [0x8fa47000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.nettrace.tool.udp.URLDataSender.run(URLDataSender.java:47)

"Thread-2" prio=10 tid=0x8fb55800 nid=0x54e7 waiting on condition [0x8fa98000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.nettrace.tool.udp.URLDataSender.run(URLDataSender.java:47)

"Thread-1" prio=10 tid=0x8fb46000 nid=0x54e4 waiting on condition [0x8fafe000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.nettrace.tool.udp.URLDataSender.run(URLDataSender.java:47)

"Thread-0" prio=10 tid=0x8fb4b400 nid=0x54e3 waiting on condition [0x8fc55000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.nettrace.tool.udp.URLDataSender.run(URLDataSender.java:47)

"Low Memory Detector" daemon prio=10 tid=0x08191000 nid=0x54e1 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x0818f800 nid=0x54e0 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x0818bc00 nid=0x54df waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0818a400 nid=0x54de runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x08172000 nid=0x54dd in Object.wait() [0x901e8000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0xaa0e99c0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0xaa0e99c0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x08170800 nid=0x54dc in Object.wait() [0x90239000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0xaa0e96a8> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0xaa0e96a8> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0816cc00 nid=0x54db runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x080f8400 nid=0x54d9 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x080f9800 nid=0x54da runnable 

"VM Periodic Task Thread" prio=10 tid=0x08192c00 nid=0x54e2 waiting on condition 

JNI global references: 1446

Heap
 PSYoungGen      total 9408K, used 3769K [0xa98d0000, 0xaa350000, 0xb4170000)
  eden space 8064K, 42% used [0xa98d0000,0xa9c2e680,0xaa0b0000)
  from space 1344K, 23% used [0xaa0b0000,0xaa100070,0xaa200000)
  to   space 1344K, 0% used [0xaa200000,0xaa200000,0xaa350000)
 PSOldGen        total 21568K, used 0K [0x94770000, 0x95c80000, 0xa98d0000)
  object space 21568K, 0% used [0x94770000,0x94770000,0x95c80000)
 PSPermGen       total 16384K, used 4649K [0x90770000, 0x91770000, 0x94770000)
  object space 16384K, 28% used [0x90770000,0x90bfa518,0x91770000)

 

1、每次执行kill -3 pid或Ctrl+break后，日志首先会记录执行的当前时间。

2、nid为十六进制的线程号，如果top –H查找的pid，在日志搜索时需要转换，pid为十进制。

3、线程的状态一般为三类：Runnable（R）当前可以运行的线程；Waiting on monitor（CW）线程主动wait； Waiting for monitor entry（MW）线程等锁（死锁）。

 

一般关注第一和第三种状态的线程,CPU很忙关注状态为runnable的线程，闲则则关注状态为waiting for monitor entry的线程。

 

 

下面给出一个典型的死锁线程（注意STUCK关键字）：

 

"[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=02fe9a18 nid=35 lwp_id=7518924 runnable [440dd000..440db878] 
at java.net.SocketInputStream.socketRead0(Native Method) 
at java.net.SocketInputStream.read(SocketInputStream.java:134) 
at weblogic.jdbc.oracle.net8.OracleDataProvider.getArrayOfBytesFromSocket(Unknown Source) 
at weblogic.jdbc.oracle.net8.OracleDataProvider.readFirstPacketInBuffer(Unknown Source) 
at weblogic.jdbc.oracle.net8.OracleDataProvider.readPacket(Unknown Source) 
at weblogic.jdbc.oracle.net8.OracleDataProvider.receive(Unknown Source) 
at weblogic.jdbc.oracle.net8.OracleNet8NSPTDAPacket.sendRequest(Unknown Source) 
at weblogic.jdbc.oracle.OracleImplStatement.fetchNext(Unknown Source) 
at weblogic.jdbc.oracle.OracleImplStatement.fetchNext2(Unknown Source) 
at weblogic.jdbc.oracle.OracleImplResultset.fetchAtPosition(Unknown Source) 
at weblogic.jdbc.base.BaseImplResultSet.next(Unknown Source) 
at weblogic.jdbc.base.BaseResultSet.next(Unknown Source) 
- locked <55f25550> (a weblogic.jdbc.oracle.OracleConnection) 
at weblogic.jdbc.wrapper.ResultSet_weblogic_jdbc_base_BaseResultSet.next(Unknown Source) 
at org.hibernate.loader.Loader.doQuery(Loader.java:685) 

 

4、heap含义

    不同的JVM的Heap信息会略不相同，有关JVM可以参看以下博文：

   1、 http://blog.csdn.net/jia20003/article/details/6608622

   2、 http://www.coderli.com/jvm-heap-code-overflow

 

 

三、阅读扩展

 

Lockness Eclipse Plugin - Thread Dump Analyser Thread Dump分析工具。