JVM分析工具——jstack實踐
一奏寨、不是萬能的jstack
企業(yè)級的Java程序中，java程序出現(xiàn)性能低下甚至直接崩潰時褒侧，就不能像解決業(yè)務(wù)bug那樣驰坊，從行為表現(xiàn)上來修復(fù)問題了。性能問題一般是jvm資源告罄的表現(xiàn)窑多，需要結(jié)合jvm的相關(guān)信息仍稀，程序日志以及程序代碼解決問題了。
jstack作為jvm分析工具之一埂息，它只能做線程轉(zhuǎn)儲堆棧分析技潘；而通常的性能問題，都是要結(jié)合jvm內(nèi)存千康，gc享幽，網(wǎng)絡(luò)，IO等諸多信息綜合分析吧秕，才能得出問題原因琉闪。有時只關(guān)注線程轉(zhuǎn)儲堆棧，而忽略其他砸彬，甚至?xí)`導(dǎo)問題線索颠毙。
但是不可否認(rèn)的是，正確分析線程轉(zhuǎn)儲堆棧砂碉，經(jīng)驗豐富的程序員直接就能把握住大方向上的問題原因蛀蜜。
二、最佳實踐
以下是分析線程轉(zhuǎn)儲堆棧的一些有效實踐：
- 虛擬機(jī)執(zhí)行Full GC時增蹭，stop the world 會阻塞其他線程滴某，Dump線程前，應(yīng)該查看內(nèi)存使用情況以及GC信息。
- 方法調(diào)用棧結(jié)合閱讀代碼推理霎奢，相互推導(dǎo)印證户誓，往往更能發(fā)現(xiàn)問題。
- Bug的原因往往不會直接在調(diào)用棧上直接體現(xiàn)幕侠，一定要注意當(dāng)前調(diào)用之前的調(diào)用情況帝美。
如何分析
拿到一段可能有問題的線程轉(zhuǎn)儲堆棧，如何入手開始分析晤硕？
- 首先關(guān)注BLOCKED 狀態(tài)的線程悼潭，分析調(diào)用棧
- 再關(guān)注WAITING 狀態(tài)的線程，分析調(diào)用棧
- 結(jié)合經(jīng)驗看問題
入手總結(jié)
Deadlock：表示有死鎖
Waiting on condition：等待某個資源或條件發(fā)生來喚醒自己舞箍。具體需要結(jié)合jstacktrace來分析舰褪，比如線程正在sleep，網(wǎng)絡(luò)讀寫繁忙而等待
Blocked：阻塞
Waiting on monitor entry：在等待獲取鎖
經(jīng)驗之談
從各種性能低下或者崩潰的java程序分析實踐中總結(jié)疏橄，有以下經(jīng)驗可供參考：
1.如果大量線程在“waiting for monitor entry”占拍，可能是一個全局鎖阻塞住了大量線程。
如果短時間內(nèi)打印的 thread dump 文件反映软族，隨著時間流逝刷喜，waiting for monitor entry 的線程越來越多残制，沒有減少的趨勢立砸，可能意味著某些線程在臨界區(qū)里呆的時間太長了，以至于越來越多新線程遲遲無法進(jìn)入臨界區(qū)初茶。
或者是因為并發(fā)太高颗祝，全局鎖的情況下，waiting for monitor entry 的線程也會很多恼布。
2.如果相同的call stack在不同時間出現(xiàn)在同一個線程上（tid）上螺戳， 有很大理由相信， 這段代碼可能存在較多的循環(huán)或者死循環(huán)折汞。
如果不同的時間多次dump線程倔幼，發(fā)現(xiàn)相同的調(diào)用棧出現(xiàn)在同一個線程上，那么說明這段時間跑的都是同一段代碼爽待，這種情況出現(xiàn)在死循環(huán)或者較多循環(huán)的代碼
3.如果某個相同的call stack經(jīng)常出現(xiàn)损同， 我們有80%的以上的理由確定這個代碼存在性能問題（讀網(wǎng)絡(luò)的部分除外）。
.
4.如果大量線程在“waiting on condition”鸟款，并且在等待網(wǎng)絡(luò)資源膏燃，可能是網(wǎng)絡(luò)瓶頸的征兆
比如說作為web容器的tomcat，某一時刻其大量線程處于WAITING 狀態(tài)何什，線程動作是 waiting on condition组哩，調(diào)用修飾有park隊列，那么說明線程正在等待網(wǎng)絡(luò)請求的接入，而這時可以進(jìn)來的網(wǎng)絡(luò)請求又少伶贰，可能是網(wǎng)絡(luò)瓶頸的征兆蛛砰，當(dāng)然也可能是這個網(wǎng)站壓根兒沒人訪問哈哈。
三黍衙、Case1 log4j1造成的性能降低
最佳實踐：
如果大量線程在“waiting for monitor entry”暴备，可能是一個全局鎖阻塞住了大量線程。
如果某個相同的call stack經(jīng)常出現(xiàn)们豌， 我們有80%的以上的理由確定這個代碼存在性能問題（讀網(wǎng)絡(luò)的部分除外）涯捻。
線程及調(diào)用棧表現(xiàn)為，大量的線程等待進(jìn)入Monitor臨界區(qū)望迎，有且僅有一個線程成功該Monitor擁有者：
大量線程處于以下狀態(tài)：
"pool-1-thread-190" prio=10 tid=0x00002b853809d800 nid=0xc01 waiting for monitor entry [0x00002b84b85d5000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at com.jlpay.commons.rpc.thrift.server.Dispatcher.invoke(Dispatcher.java:38)
at com.jlpay.commons.rpc.thrift.server.RpcAdapterImpl.Invoke(RpcAdapterImpl.java:32)
at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:175)
at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:160)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.invoke(AbstractNonblockingServer.java:518)
at org.apache.thrift.server.Invocation.run(Invocation.java:18)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
僅有一個線程進(jìn)入臨界區(qū)（注意獲得的鎖地址與以上等待的鎖地址相同）
"pool-1-thread-102" prio=10 tid=0x00002b8538053800 nid=0xba9 runnable [0x00002b84b2f71000]
java.lang.Thread.State: RUNNABLE
at java.text.DateFormat.format(DateFormat.java:336)
at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:443)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x0000000788057650> (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)
原因是全局鎖的存在導(dǎo)致性能降低障癌，此乃log4j1的缺陷，升級日志實現(xiàn)即可辩尊。
四涛浙、Case2 web會話未釋放導(dǎo)致的服務(wù)崩潰
最佳實踐：
Dump線程前，先查看分析jvm內(nèi)存信息
五摄欲、Case3 一個load飆高的過程分析
refer to 一個load飆高的過程分析轿亮，非常有價值
六、Case4 死鎖
jstack -l <pid> 可以檢測到死鎖：
"Thread-1" #12 prio=5 os_prio=0 tid=0x000000001e9df000 nid=0x3a78 waiting for monitor entry [0x000000001f3cf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.JStackDeadLock.fun2(JStackDeadLock.java:31)
- waiting to lock <0x000000076b881790> (a java.lang.Object)
- locked <0x000000076b8817a0> (a java.lang.Object)
at jstack.JStackDeadLock$$Lambda$2/2074407503.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
"Thread-0" #11 prio=5 os_prio=0 tid=0x000000001e9de800 nid=0x4244 waiting for monitor entry [0x000000001f2ce000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.JStackDeadLock.fun1(JStackDeadLock.java:21)
- waiting to lock <0x000000076b8817a0> (a java.lang.Object)
- locked <0x000000076b881790> (a java.lang.Object)
at jstack.JStackDeadLock$$Lambda$1/558638686.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x0000000002c3a758 (object 0x000000076b881790, a java.lang.Object),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x000000001e9ed038 (object 0x000000076b8817a0, a java.lang.Object),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at jstack.JStackDeadLock.fun2(JStackDeadLock.java:31)
- waiting to lock <0x000000076b881790> (a java.lang.Object)
- locked <0x000000076b8817a0> (a java.lang.Object)
at jstack.JStackDeadLock$$Lambda$2/2074407503.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
"Thread-0":
at jstack.JStackDeadLock.fun1(JStackDeadLock.java:21)
- waiting to lock <0x000000076b8817a0> (a java.lang.Object)
- locked <0x000000076b881790> (a java.lang.Object)
at jstack.JStackDeadLock$$Lambda$1/558638686.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
Found 1 deadlock.
可以輕易直觀分析胸墙，兩個鎖被兩個線程相互持有我注。
七、Case5 CPU占用高
refer to 如何使用jstack分析線程狀態(tài)
案例持續(xù)加入中...
