Sun中國技術(shù)社區(qū)- Sun Developer Network (SDN) Home

ShangShujie 2007-03-28

展開全文

JAVA線程dump的分析

By Carol Zhang, 11/9/06

Java 的線程

線程是指能獨立于程序的其它部分運行的執(zhí)行單元。 JAVA語言能夠很好的實現(xiàn)多線程的程序。我們在調(diào)試程序，或者在開發(fā)后期需要做性能調(diào)優(yōu)的時候，往往也需要了解當(dāng)前程序正在運行的線程的狀態(tài)，正在執(zhí)行的操作，從而分析系統(tǒng)可能存在的問題。

在閱讀本文之間，應(yīng)對 Java線程的編程原理，同步機制有一定了解 .

產(chǎn)生 JAVA線程 dump

JAVA 的線程 DUMP，就象當(dāng)前 JAVA進程的一個快照，打印出所有線程的狀態(tài)和調(diào)用堆棧，以及 Monitor的狀態(tài)。在不同的操作系統(tǒng)下，產(chǎn)生線程 DUMP的方式是不同的。

·在 windows環(huán)境中，

在啟動程序的控制臺里敲： Ctrl - Break，線程的 dump會產(chǎn)生在標(biāo)準(zhǔn)輸出中（缺省標(biāo)準(zhǔn)輸出就是控制臺，如果對輸出進行了重定向，則要查看輸出文件）。

在 unix， linux和 MacOS 環(huán)境中，

在控制臺中敲： Ctrl-\，或者，
用 “kill -3 <pid>” ，或者 “kill – QUIT <pid>”。 Pid是用所關(guān)注的 JAVA進程號，您可以用 “ps -ef | grep java” 找到，或者使用 JDK 5.0中的 “jps -v” 命令獲得。

在各個操作系統(tǒng)平臺，都可以用 JDK 5.0工具包中的 jstack <pid>

這里要注意的是：

1. 不同的 JAVA虛機的線程 DUMP的創(chuàng)建方法和文件格式是不一樣的，不同的 JVM版本， dump信息也有差別。本文中，只以 SUN的 hotspot JVM 5.0_06 為例。

2. 在實際運行中，往往一次 dump的信息，還不足以確認問題。建議產(chǎn)生三次 dump信息，如果每次 dump都指向同一個問題，我們才確定問題的典型性。

線程分析：

1.     JVM 線程
在線程中，有一些 JVM內(nèi)部的后臺線程，來執(zhí)行譬如垃圾回收，或者低內(nèi)存的檢測等等任務(wù)，這些線程往往在 JVM初始化的時候就存在，如下所示：

        "Low Memory Detector" daemon prio=10 tid=0x081465f8 nid=0x7 runnable [0x00000000..0x00000000]

        "CompilerThread0" daemon prio=10 tid=0x08143c58 nid=0x6 waiting on condition [0x00000000..0xfb5fd798]

        "Signal Dispatcher" daemon prio=10 tid=0x08142f08 nid=0x5 waiting on condition [0x00000000..0x00000000]

        "Finalizer" daemon prio=10 tid=0x08137ca0 nid=0x4 in Object.wait() [0xfbeed000..0xfbeeddb8]

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

        - waiting on <0xef600848> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)

        - locked <0xef600848> (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=10 tid=0x081370f0 nid=0x3 in Object.wait() [0xfbf4a000..0xfbf4aa38]

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

        - waiting on <0xef600758> (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 <0xef600758> (a java.lang.ref.Reference$Lock)

        "VM Thread" prio=10 tid=0x08134878 nid=0x2 runnable

        "VM Periodic Task Thread" prio=10 tid=0x08147768 nid=0x8 waiting on condition



                我們更多的是要觀察用戶級別的線程，如下所示：

        "Thread-1" prio=10 tid=0x08223860 nid=0xa waiting on condition [0xef47a000..0xef47ac38]

        at java.lang.Thread.sleep(Native Method)

        at testthread.MySleepingThread.method2(MySleepingThread.java:53)

        - locked <0xef63d600> (a testthread.MySleepingThread)

        at testthread.MySleepingThread.run(MySleepingThread.java:35)

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

        我們能看到：

線程的狀態(tài)： waiting on condition

線程的調(diào)用棧

線程的當(dāng)前鎖住的資源： <0xef63d600>

這些信息對我們隨后的分析都有用處。

2. 線程的狀態(tài)分析

正如我們剛看到的那樣，線程的狀態(tài)是一個重要的指標(biāo)，它會顯示在線程 Stacktrace的頭一行結(jié)尾的地方。那么線程常見的有哪些狀態(tài)呢？線程在什么樣的情況下會進入這種狀態(tài)呢？我們能從中發(fā)現(xiàn)什么線索？< /span>

1.1 Runnable

該狀態(tài)表示線程具備所有運行條件，在運行隊列中準(zhǔn)備操作系統(tǒng)的調(diào)度，或者正在運行。

1.2 Wait on condition

該狀態(tài)出現(xiàn)在線程等待某個條件的發(fā)生。具體是什么原因，可以結(jié)合 stacktrace來分析。最常見的情況是線程在等待網(wǎng)絡(luò)的讀寫，比如當(dāng)網(wǎng)絡(luò)數(shù)據(jù)沒有準(zhǔn)備好讀時，線程處于這種等待狀態(tài)，而一旦有數(shù)據(jù)準(zhǔn)備好讀之后，線程會重新激活，讀取并處理數(shù)據(jù)。在 Java引入 NewIO之前，對于每個網(wǎng)絡(luò)連接，都有一個對應(yīng)的線程來處理網(wǎng)絡(luò)的讀寫操作，即使沒有可讀寫的數(shù)據(jù)，線程仍然阻塞在讀寫操作上，這樣有可能造成資源浪費，而且給操作系統(tǒng)的線程調(diào)度也帶來壓力。在 NewIO里采用了新的機制，編寫的服務(wù)器程序的性能和可擴展性都得到提高。

如果發(fā)現(xiàn)有大量的線程都在處在 Wait on condition，從線程 stack看，正等待網(wǎng)絡(luò)讀寫，這可能是一個網(wǎng)絡(luò)瓶頸的征兆。因為網(wǎng)絡(luò)阻塞導(dǎo)致線程無法執(zhí)行。一種情況是網(wǎng)絡(luò)非常忙，幾乎消耗了所有的帶寬，仍然有大量數(shù)據(jù)等待網(wǎng)絡(luò)讀寫；另一種情況也可能是網(wǎng)絡(luò)空閑，但由于路由等問題，導(dǎo)致包無法正常的到達。所以要結(jié)合系統(tǒng)的一些性能觀察工具來綜合分析，比如 netstat統(tǒng)計單位時間的發(fā)送包的數(shù)目，如果很明顯超過了所在網(wǎng)絡(luò)帶寬的限制 ; 觀察 cpu的利用率，如果系統(tǒng)態(tài)的 CPU時間，相對于用戶態(tài)的 CPU時間比例較高；如果程序運行在 Solaris 10平臺上，可以用 dtrace工具看系統(tǒng)調(diào)用的情況，如果觀察到 read/write的系統(tǒng)調(diào)用的次數(shù)或者運行時間遙遙領(lǐng)先；這些都指向由于網(wǎng)絡(luò)帶寬所限導(dǎo)致的網(wǎng)絡(luò)瓶頸。

另外一種出現(xiàn) Wait on condition的常見情況是該線程在 sleep，等待 sleep的時間到了時候，將被喚醒。

1.3 Waiting for monitor entry 和 in Object.wait()

在多線程的 JAVA程序中，實現(xiàn)線程之間的同步，就要說說 Monitor。 Monitor是 Java中用以實現(xiàn)線程之間的互斥與協(xié)作的主要手段，它可以看成是對象或者 Class的鎖。每一個對象都有，也僅有一個 monitor。下面這個圖，描述了線程和 Monitor之間關(guān)系，以及線程的狀態(tài)轉(zhuǎn)換圖：

從圖中可以看出，每個 Monitor在某個時刻，只能被一個線程擁有，該線程就是 “Active Thread”，而其它線程都是 “Waiting Thread”，分別在兩個隊列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的線程狀態(tài)是 “Waiting for monitor entry”，而在 “Wait Set”中等待的線程狀態(tài)是 “in Object.wait()”。

先看 “Entry Set”里面的線程。我們稱被 synchronized保護起來的代碼段為臨界區(qū)。當(dāng)一個線程申請進入臨界區(qū)時，它就進入了 “Entry Set”隊列。對應(yīng)的 code就像：

synchronized(obj) {
.........

}

這時有兩種可能性：

·          該 monitor不被其它線程擁有， Entry Set里面也沒有其它等待線程。本線程即成為相應(yīng)類或者對象的 Monitor的 Owner，執(zhí)行臨界區(qū)的代碼

·          該 monitor被其它線程擁有，本線程在 Entry Set隊列中等待。

在第一種情況下，線程將處于 “Runnable”的狀態(tài)，而第二種情況下，線程 DUMP會顯示處于 “waiting for monitor entry”。如下所示：

"Thread-0" prio=10 tid=0x08222eb0 nid=0x9 waiting for monitor entry [0xf927b000..0xf927bdb8]

at testthread.WaitThread.run(WaitThread.java:39)

- waiting to lock <0xef63bf08> (a java.lang.Object)

- locked <0xef63beb8> (a java.util.ArrayList)

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

臨界區(qū)的設(shè)置，是為了保證其內(nèi)部的代碼執(zhí)行的原子性和完整性。但是因為臨界區(qū)在任何時間只允許線程串行通過，這和我們多線程的程序的初衷是相反的。如果在多線程的程序中，大量使用 synchronized，或者不適當(dāng)?shù)氖褂昧怂?，會造成大量線程在臨界區(qū)的入口等待，造成系統(tǒng)的性能大幅下降。如果在線程 DUMP中發(fā)現(xiàn)了這個情況，應(yīng)該審查源碼，改進程序。

現(xiàn)在我們再來看現(xiàn)在線程為什么會進入 “Wait Set”。當(dāng)線程獲得了 Monitor，進入了臨界區(qū)之后，如果發(fā)現(xiàn)線程繼續(xù)運行的條件沒有滿足，它則調(diào)用對象（一般就是被 synchronized 的對象）的 wait() 方法，放棄了 Monitor，進入 “Wait Set”隊列。只有當(dāng)別的線程在該對象上調(diào)用了 notify() 或者 notifyAll() ， “ Wait Set”隊列中線程才得到機會去競爭，但是只有一個線程獲得對象的 Monitor，恢復(fù)到運行態(tài)。在 “Wait Set”中的線程， DUMP中表現(xiàn)為： in Object.wait()，類似于：

        "Thread-1" prio=10 tid=0x08223250 nid=0xa in Object.wait() [0xef47a000..0xef47aa38]

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

        - waiting on <0xef63beb8> (a java.util.ArrayList)

        at java.lang.Object.wait(Object.java:474)

        at testthread.MyWaitThread.run(MyWaitThread.java:40)

        - locked <0xef63beb8> (a java.util.ArrayList)

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

仔細觀察上面的 DUMP信息，你會發(fā)現(xiàn)它有以下兩行：

- locked <0xef63beb8> (a java.util.ArrayList)

- waiting on <0xef63beb8> (a java.util.ArrayList)

這里需要解釋一下，為什么先 lock了這個對象，然后又 waiting on同一個對象呢？讓我們看看這個線程對應(yīng)的代碼：

        synchronized(obj) {
               .........
               obj.wait();
               .........
        }

線程的執(zhí)行中，先用 synchronized 獲得了這個對象的 Monitor（對應(yīng)于 locked <0xef63beb8> ）。當(dāng)執(zhí)行到 obj.wait(), 線程即放棄了 Monitor的所有權(quán)，進入 “wait set”隊列（對應(yīng)于 waiting on <0xef63beb8> ）。

往往在你的程序中，會出現(xiàn)多個類似的線程，他們都有相似的 DUMP信息。這也可能是正常的。比如，在程序中，有多個服務(wù)線程，設(shè)計成從一個隊列里面讀取請求數(shù)據(jù)。這個隊列就是 lock以及 waiting on的對象。當(dāng)隊列為空的時候，這些線程都會在這個隊列上等待，直到隊列有了數(shù)據(jù)，這些線程被 Notify，當(dāng)然只有一個線程獲得了 lock，繼續(xù)執(zhí)行，而其它線程繼續(xù)等待。

3.     JDK 5.0 的 lock

上面我們提到如果 synchronized和 monitor機制運用不當(dāng)，可能會造成多線程程序的性能問題。在 JDK 5.0中，引入了 Lock機制，從而使開發(fā)者能更靈活的開發(fā)高性能的并發(fā)多線程程序，可以替代以往 JDK中的 synchronized和 Monitor的機制。但是，要注意的是，因為 Lock類只是一個普通類， JVM無從得知 Lock對象的占用情況，所以在線程 DUMP中，也不會包含關(guān)于 Lock的信息，關(guān)于死鎖等問題，就不如用 synchronized的編程方式容易識別。

案例分析

1. 死鎖

在多線程程序的編寫中，如果不適當(dāng)?shù)倪\用同步機制，則有可能造成程序的死鎖，經(jīng)常表現(xiàn)為程序的停頓，或者不再響應(yīng)用戶的請求。

比如在下面這個示例中，是個較為典型的死鎖情況：

"Thread-1" prio=5 tid=0x00acc490 nid=0xe50 waiting for monitor entry [0x02d3f000

..0x02d3fd68]

at deadlockthreads.TestThread.run(TestThread.java:31)

- waiting to lock <0x22c19f18> (a java.lang.Object)

- locked <0x22c19f20> (a java.lang.Object)

"Thread-0" prio=5 tid=0x00accdb0 nid=0xdec waiting for monitor entry [0x02cff000

..0x02cff9e8]

at deadlockthreads.TestThread.run(TestThread.java:31)

- waiting to lock <0x22c19f20> (a java.lang.Object)

- locked <0x22c19f18> (a java.lang.Object)

在 JAVA 5中加強了對死鎖的檢測。線程 Dump中可以直接報告出 Java級別的死鎖，如下所示：

Found one Java-level deadlock:

=============================

"Thread-1":

waiting to lock monitor 0x0003f334 (object 0x22c19f18, a java.lang.Object),

which is held by "Thread-0"

"Thread-0":

waiting to lock monitor 0x0003f314 (object 0x22c19f20, a java.lang.Object),

which is held by "Thread-1"

2. 熱鎖

熱鎖，也往往是導(dǎo)致系統(tǒng)性能瓶頸的主要因素。其表現(xiàn)特征為，由于多個線程對臨界區(qū)，或者鎖的競爭，可能出現(xiàn)：& amp; lt; /span>

頻繁的線程的上下文切換：從操作系統(tǒng)對線程的調(diào)度來看，當(dāng) 線程在等待資源而阻塞的時候，操作系統(tǒng)會將之切換出來，放到等待的隊列，當(dāng)線程獲得資源之后，調(diào)度算法會將這個線程切換進去，放到執(zhí)行隊列中。& amp; amp; amp; lt; /li>

大量的系統(tǒng)調(diào)用：因為線程的上下文切換，以及熱鎖的競爭，或者臨界區(qū)的頻繁的進出，都可能導(dǎo)致大量的系統(tǒng)調(diào)用。M t < /span>

大部分 CPU開銷用在 “系統(tǒng)態(tài) ”：線程上下文切換，和系統(tǒng)調(diào)用，都會導(dǎo)致 CPU在 “系統(tǒng)態(tài) ”運行，換而言之，雖然系統(tǒng)很忙碌，但是 CPU用在 “用戶態(tài) ”的比例較小，應(yīng)用程序得不到充分的 CPU資源。

隨著 CPU數(shù)目的增多，系統(tǒng)的性能反而下降。因為 CPU數(shù)目多，同時運行的線程就越多，可能就會造成更頻繁的線程上下文切換和系統(tǒng)態(tài)的 CPU開銷，從而導(dǎo)致更糟糕的性能。

上面的描述，都是一個 scalability（可擴展性）很差的系統(tǒng)的表現(xiàn)。從整體的性能指標(biāo)看，由于線程熱鎖的存在，程序的響應(yīng)時間會變長，吞吐量會降低。< /span>

那么，怎么去了解 “熱鎖 ”出現(xiàn)在什么地方呢？一個重要的方法還是結(jié)合操作系統(tǒng)的各種工具觀察系統(tǒng)資源使用狀況，以及收集 Java線程的 DUMP信息，看線程都阻塞在什么方法上，了解原因，才能找到對應(yīng)的解決方法。

我們曾經(jīng)遇到過這樣的例子，程序運行時，出現(xiàn)了以上指出的各種現(xiàn)象，通過觀察操作系統(tǒng)的資源使用統(tǒng)計信息，以及線程 DUMP信息，確定了程序中熱鎖的存在，并發(fā)現(xiàn)大多數(shù)的線程狀態(tài)都是 Waiting for monitor entry或者 Wait on monitor，且是阻塞在壓縮和解壓縮的方法上。后來采用第三方的壓縮包 javalib替代 JDK自帶的壓縮包后，系統(tǒng)的性能提高了幾倍。