如何分析Java虛擬機(jī)死鎖
我發(fā)現(xiàn)現(xiàn)在網(wǎng)上沒(méi)有好好講這個(gè)的，少數(shù)的幾篇文章都是大談自己的工具，卻沒(méi)把方法講清楚。我決定以我以前碰到的case為例寫(xiě)一篇來(lái)分享。
到目前為止，我認(rèn)為分析Java代碼問(wèn)題的最有效的工具仍然是java thread dump。原因：
- 任何操作系統(tǒng)平臺(tái)下都可以使用。
- 在多數(shù)情況下，可以在生產(chǎn)環(huán)境中使用。
- 和操作系統(tǒng)提供的工具相比，java thread dump給出的信息是直白的，直接對(duì)應(yīng)到應(yīng)用代碼。
- 它對(duì)被分析的系統(tǒng)干擾很小，因此能反應(yīng)真實(shí)的問(wèn)題。而其它很多profiling或Instrument工具本身對(duì)JVM運(yùn)行有很大的干擾，經(jīng)常不能暴露出真正的問(wèn)題，而且這種工具不能用于生產(chǎn)系統(tǒng)。
我覺(jué)得在通常情況下分析Java虛擬機(jī)死鎖比分析內(nèi)存泄漏要容易的多。因?yàn)樗梨i發(fā)生時(shí)，JVM通常處于掛起狀態(tài)(hang住了)，thread dump可以給出靜態(tài)穩(wěn)定的信息，查找死鎖只需要查找有問(wèn)題的線程。而內(nèi)存泄漏的問(wèn)題卻很難界定，一個(gè)運(yùn)行的JVM里有無(wú)數(shù)對(duì)象存在，只有寫(xiě)程序的人才知道哪些對(duì)象是垃圾，而哪些不是，而且對(duì)象的引用關(guān)系非常復(fù)雜，很難得到一份清晰的對(duì)象引用圖。
Java虛擬機(jī)死鎖發(fā)生時(shí)，從操作系統(tǒng)上觀察，虛擬機(jī)的CPU占用率為零，很快會(huì)從top或prstat的輸出中消失。這時(shí)你就可以收集thread dump了，Unix/Linux 下是kill -3 <JVM pid>，在Windows下可以在JVM的console窗口上敲Ctrl-Break。根據(jù)不同的設(shè)置，thread dump會(huì)輸出到當(dāng)前控制臺(tái)上或應(yīng)用服務(wù)器的日志里。
拿到j(luò)ava thread dump后，你要做的就是查找"waiting for monitor entry"的thread，如果大量thread都在等待給同一個(gè)地址上鎖（因?yàn)閷?duì)于Java，一個(gè)對(duì)象只有一把鎖），這說(shuō)明很可能死鎖發(fā)生了。比如：
"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)
................
為了確定問(wèn)題，常常需要在隔兩分鐘后再次收集一次thread dump，如果得到的輸出相同，仍然是大量thread都在等待給同一個(gè)地址上鎖，那么肯定是死鎖了。
如何找到當(dāng)前持有鎖的線程是解決問(wèn)題的關(guān)鍵。方法是搜索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)
在這個(gè)例子里，持有鎖的線程在等待Oracle返回結(jié)果，卻始終等不到響應(yīng)，因此發(fā)生了死鎖。
如果持有鎖的線程還在等待給另一個(gè)對(duì)象上鎖，那么還是按上面的辦法順藤摸瓜，直到找到死鎖的根源為止。
另外，在thread dump里還會(huì)經(jīng)常看到這樣的線程，它們是等待一個(gè)條件而主動(dòng)放棄鎖的線程。例如：
"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)
有時(shí)也會(huì)需要分析這類(lèi)線程，尤其是線程等待的條件。
其實(shí)，Java thread dump并不只用于分析死鎖，其它Java應(yīng)用運(yùn)行時(shí)古怪的行為都可以用thread dump來(lái)分析。
最后，在Java SE 5里，增加了jstack的工具，也可以獲取thread dump。在Java SE 6里， 通過(guò)jconsole的圖形化工具也可以方便地查找涉及object monitors 和java.util.concurrent.locks死鎖。