Thread Dump and Concurrency Locks

Thread dumps are very useful for diagnosing synchronization related problems such as deadlocks on object monitors. Ctrl-\ on Solaris/Linux or Ctrl-Break on Windows has been a common way to get a thread dump of a running application. O n Solaris or Linux, you can send a QUIT signal to the target application. The target application in both cases prints a thread dump to the standard output and also detects if there is any deadlock involving object monitors.

jstack , a new troubleshooting utility introduced in Tiger (J2SE 5.0), provides another way to obtain a thread dump of an application. Alan Bateman has a nice blog about jstack and its several improvements in Mustang (Java SE 6). Mustang jstack works like a remote Ctrl-\ or Ctrl-Break if you are on Windows.

jconsole is JMX-complaint GUI tool which allows you to get a thread dump on the fly. The “Using JConsole to Monitor Applications ” article gives you an overview of the Tiger monitoring and management functionality.

Mustang extends the thread dump, jstack, and jconsole to support java.util.concurrent.locks to improve its diagnosability. For example, the Threads tab in the Mustang jconsole now shows which synchronizer a thread is waiting to acquire when the thread is blocked to lock a ReentrantLock and also which thread is owning that lock.

In addition, it has a new “detect deadlock” button (in the bottom). When you click on the “detect deadlock” button, it will send a request to the target application to perform the deadlock detection operation. If the target application is running on Mustang, it finds deadlocks involving both object monitors as well as the java.util.concurrent.locks. If the target application is running on Tiger, it finds deadlocks involving object monitors only. Each deadlock cycle will be displayed in a separate Deadlock tab.

Click here to see a wider form of this screenshot.

JDK 6 has a nice demo FullThreadDump under $JDK_HOME/demo/management/FullThreadDump where JDK_HOME is the location of your JDK 6. This demo has been included in JDK 5.0 and is updated to use the new Mustang API. It demonstrates the use of the java.lang.management API to get the thread dump and detect deadlock programmatically.

中文资料：

我发现现在网上没有好好讲这个的，少数的几篇文章都是大谈自己的工具，却没把方法讲清楚。我决定以我以前碰到的case为例写一篇来分享。到目前为止，我认为分析Java代码问题的最有效的工具仍然是java thread dump。

原因：

– 任何操作系统平台下都可以使用。

– 在多数情况下，可以在生产环境中使用。

– 和操作系统提供的工具相比，java thread dump给出的信息是直白的，直接对应到应用代码。

– 它对被分析的系统干扰很小，因此能反应真实的问题。而其它很多profiling或Instrument工具本身对JVM运行有很大的干扰，经常不能暴露出真正的问题，而且这种工具不能用于生产系统。

我觉得在通常情况下分析Java虚拟机死锁比分析内存泄漏要容易的多。因为死锁发生时，JVM通常处于挂起状态(hang住了)，thread dump可以给出静态稳定的信息，查找死锁只需要查找有问题的线程。而内存泄漏的问题却很难界定，一个运行的JVM里有无数对象存在，只有写程序的人才知道哪些对象是垃圾，而哪些不是，而且对象的引用关系非常复杂，很难得到一份清晰的对象引用图。

Java虚拟机死锁发生时，从操作系统上观察，虚拟机的CPU占用率为零，很快会从top或prstat的输出中消失。这时你就可以收集thread dump了，Unix/Linux 下是kill -3 <JVM pid> ，在Windows下可以在JVM的console窗口上敲Ctrl-Break。根据不同的设置，thread dump会输出到当前控制台上或应用服务器的日志里。

拿到java thread dump后，你要做的就是查找”waiting for monitor entry”的thread，如果大量thread都在等待给同一个地址上锁（因为对于Java，一个对象只有一把锁），这说明很可能死锁发生了。比如：

“service-j2ee” prio=5 tid=0x024f1c28 nid=0x125 waiting for monitor entry

[62a3e000..62a3f690]

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.internalGetResource(IASNonS

haredResourcePool.java:625)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: – waiting to

lock <0x965d8110> (a com.sun.enterprise.resource.IASNonSharedResourcePool)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.getResource(IASNonSharedRes

ourcePool.java:520)

…………….

为了确定问题，常常需要在隔两分钟后再次收集一次thread dump，如果得到的输出相同，仍然是大量thread都在等待给同一个地址上锁，那么肯定是死锁了。

如何找到当前持有锁的线程是解决问题的关键。方法是搜索thread dump，查找”locked <0x965d8110>”， 找到持有锁的线程。

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: “Thread-20” daemon prio=5 tid=0x01394f18

nid=0x109 runnable [6716f000..6716fc28]

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.net.SocketInputStream.socketRead0(Native Method)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.net.SocketInputStream.read(SocketInputStream.java:129)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at oracle.net.ns.Packet.receive(Unknown

Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.DataPacket.receive(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.net.ns.NetInputStream.read(Unknown Source)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.MAREngine.unmarshalUB1(MAREngine.java:929)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.MAREngine.unmarshalSB1(MAREngine.java:893)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.Ocommoncall.receive(Ocommoncall.java:106)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.ttc7.TTC7Protocol.logoff(TTC7Protocol.java:396)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: – locked <0x954f47a0> (a

oracle.jdbc.ttc7.TTC7Protocol)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

oracle.jdbc.driver.OracleConnection.close(OracleConnection.java:1518)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: – locked <0x954f4520> (a

oracle.jdbc.driver.OracleConnection)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.JdbcUrlAllocator.destroyResource(JdbcUrlAllocator.java:122)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.destroyResource(IASNonSharedResourcePool.java:8

72)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool.resizePool(IASNonSharedResourcePool.java:1086)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: – locked <0x965d8110> (a

com.sun.enterprise.resource.IASNonSharedResourcePool)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

com.sun.enterprise.resource.IASNonSharedResourcePool$Resizer.run(IASNonSharedResourcePool.java:1178)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.util.TimerThread.mainLoop(Timer.java:432)

[27/Jun/2006:10:03:08] WARNING (26140): CORE3283: stderr: at

java.util.TimerThread.run(Timer.java:382)

在这个例子里，持有锁的线程在等待Oracle返回结果，却始终等不到响应，因此发生了死锁。

如果持有锁的线程还在等待给另一个对象上锁，那么还是按上面的办法顺藤摸瓜，直到找到死锁的根源为止。

另外，在thread dump里还会经常看到这样的线程，它们是等待一个条件而主动放弃锁的线程。例如：

“Thread-1” daemon prio=5 tid=0x014e97a8 nid=0x80 in Object.wait() [68c6f000..68c6fc28]

at java.lang.Object.wait(Native Method)

– waiting on <0x95b07178> (a java.util.LinkedList)

at com.iplanet.ias.util.collection.BlockingQueue.remove(BlockingQueue.java:258)

– locked <0x95b07178> (a java.util.LinkedList)

at com.iplanet.ias.util.threadpool.FastThreadPool$ThreadPoolThread.run(FastThreadPool.java:241)

at java.lang.Thread.run(Thread.java:534)

有时也会需要分析这类线程，尤其是线程等待的条件。

其实，Java thread dump并不只用于分析死锁，其它Java应用运行时古怪的行为都可以用thread dump来分析。

最后，在Java SE 5里，增加了jstack的工具，也可以获取thread dump。在Java SE 6里， 通过jconsole的图形化工具也可以方便地查找涉及object monitors 和java.util.concurrent.locks死锁。