昨天聊了性能測試指標和性能測試排除過程，主要是理論，今后幾天主要講案例。
延遲高有很多叫法，比如響應時間長、服務器反應慢、業(yè)務超時等，最根本的表現(xiàn)就是客戶端發(fā)送請求到服務端后，服務器很長時間才給應答或者根本就沒給應答。
造成延遲高（響應時間長）的原因有很多，比如：
- 服務端應用壓力太大，確實處理不過來了
- 使用了不恰當?shù)耐芥i（代碼級別或者其他資源鎖）
- 第三方資源的不給力
- 線程池配置的不合理，線程數(shù)配置的太少導致的請求積壓
- 網(wǎng)絡原因，丟包、帶寬限制、重傳等
- sleep
- 調用端代碼有問題導致服務器應答到達客戶端后，客戶端處理不及時，可能也會誤認為響應時間長
分析方法
用到的工具
- jvisualvm
用于實時的監(jiān)控每個方法的執(zhí)行時間，統(tǒng)計比較精但不適合線上長時間使用。 - jstack
抓取應用當前的線程堆棧信息，分析每個線程正在執(zhí)行的操作。
通過jvisualvm分析
通過jvisualvm分析能夠更直觀的看到每個方法的執(zhí)行時間，在測試環(huán)境或者開發(fā)階段調優(yōu)非常有幫助。
首先，打開jvisualvm，jvisualvm位于jdk的bin目錄下，一般配置了jdk的環(huán)境變量可以直接通過命令行輸入jvisualvm打開。另外也可以通過https://visualvm.github.io/去下載直接使用。
打開后界面如下：
如果是本地應用，可以直接點擊需要監(jiān)控的進程，直接掛載上去。
如果是遠程應用，需要在遠程應用啟動的時候，添加允許遠程調試的參數(shù)。
-Dcom.sun.management.jmxremote.port=8999 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.rmi.server.hostname=遠程機器IP 掛載成功后點擊抽樣器標簽，抽樣選擇CPU，點擊完后就開始監(jiān)控了。
監(jiān)控一段時間后，一般幾十秒后就可以了，點擊快照抓取監(jiān)控的快照，為了保險可以在運行幾十秒后再抓取一次快照，為了對比確定問題。然后就可以停止監(jiān)控了。
快照抓取成功后會在最右側的標簽中展示，如下圖：
打開第一次的快照，選擇熱點標簽，按總時間排序，排序后左側的方法區(qū)就是執(zhí)行時間比較長的方法。如下圖所示。但是這其實不是我們想要的，你應該能看到執(zhí)行時間長的都是些select、wait、sleep等，這些類似一些基本操作的方法，執(zhí)行的次數(shù)比較多，還有就是設計的就是要等待的操作，所以執(zhí)行的時間比較長。
比較靠譜的做法是，我們先大概過一下，如果沒有明顯的有問題的方法的話，而且方法也很多的話，可以根據(jù)包名過濾一下，只關注我們自己的東西，看看我們開發(fā)的方法中那些方法執(zhí)行時間比較長。比如如下所示，我過濾下demo包的方法。
此時可以發(fā)現(xiàn)一些執(zhí)行時間比較長的方法，發(fā)現(xiàn)以后可以通過右鍵在調用樹中查找，確定該方法執(zhí)行時間長具體是因為哪一步導致的。如下圖：
現(xiàn)在可以發(fā)現(xiàn)，執(zhí)行時間戳是因為本地的test調用遠端的delay方法導致的，可以查看遠程的delay代碼優(yōu)化了。
通過線程堆棧分析
生產環(huán)境中，大多數(shù)情況下沒有條件通過jvisualvm的方式分析，因此只能通過執(zhí)行堆棧來分析。
通過堆棧分析的話，最好是在應用出問題提交明顯的情況下分析。
線程分析的根本為同一時間點同時執(zhí)行某項任務的幾率比較低，每次都被抓到的概率更低，如果每次都有相同的執(zhí)行堆棧被抓取到，那肯定是有原因的，要么是長態(tài)任務，要么是有問題。
抓取線程堆棧
首先通過jstack命令抓取線程的執(zhí)行堆棧，連續(xù)抓取3次對比用，每次間隔幾秒。
jstack 進程ID > /tmp/文件名.jstack
分析
分析抓取的線程堆棧，這個比較麻煩，需要你對該應用有一定的了解，能夠看到堆棧大概知道所對應的功能。
大概堆棧文件后，先大概的過一遍堆棧的信息，線程數(shù)比較多的話，可能要通過以下統(tǒng)計的方法過一下，要知道這么多線程中每個種類線程執(zhí)行的操作的一個分布，比如多少io線程，每個線程池多少線程，多少wait線程等。
一般情況下響應時間長，在線程堆棧上的表現(xiàn)為有大量的線程在執(zhí)行同一個操作，或者有大量線程在等同一個資源，在檢查堆棧的時候我們可以重點去觀察一下。
示例 - 鎖等待導致的響應時間長
在遇到堆棧中有大量的BLOCKED線程的情況下，如要確定是不是用了某些不合適的同步鎖。
以下是一個鎖等待導致的響應時間長的堆棧信息的摘取，可以看到大量的堆棧都在waiting一個lock。
另外，線程池中沒有任務，或者大量的Queue的等待的話，線程池中的線程也會是blocked或者wait的狀態(tài)，但是這個是正常的，因為他就是沒事可做，在等待任務。
"Thread-96" #116 prio=5 os_prio=0 tid=0x00007f4efc677800 nid=0x2ba9 waiting for monitor entry [0x00007f4e69ddc000]
java.lang.Thread.State: BLOCKED (on object monitor)
at main.java.demo.delay.Client.testDelay(Client.java:47)
- waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
at main.java.demo.delay.Client$1.run(Client.java:31)
at java.lang.Thread.run(Thread.java:745)
"Thread-95" #115 prio=5 os_prio=0 tid=0x00007f4efc675800 nid=0x2ba8 waiting for monitor entry [0x00007f4e69edd000]
java.lang.Thread.State: BLOCKED (on object monitor)
at main.java.demo.delay.Client.testDelay(Client.java:47)
- waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
at main.java.demo.delay.Client$1.run(Client.java:31)
at java.lang.Thread.run(Thread.java:745)
"Thread-94" #114 prio=5 os_prio=0 tid=0x00007f4efc673800 nid=0x2ba7 waiting for monitor entry [0x00007f4e69fde000]
java.lang.Thread.State: BLOCKED (on object monitor)
at main.java.demo.delay.Client.testDelay(Client.java:47)
- waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
at main.java.demo.delay.Client$1.run(Client.java:31)
at java.lang.Thread.run(Thread.java:745)
"Thread-93" #113 prio=5 os_prio=0 tid=0x00007f4efc671800 nid=0x2ba6 waiting for monitor entry [0x00007f4e6a0df000]
java.lang.Thread.State: BLOCKED (on object monitor)
at main.java.demo.delay.Client.testDelay(Client.java:47)
- waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
at main.java.demo.delay.Client$1.run(Client.java:31)
at java.lang.Thread.run(Thread.java:745)
"Thread-92" #112 prio=5 os_prio=0 tid=0x00007f4efc66f800 nid=0x2ba5 waiting for monitor entry [0x00007f4e6a1e0000]
java.lang.Thread.State: BLOCKED (on object monitor)
at main.java.demo.delay.Client.testDelay(Client.java:47)
- waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
at main.java.demo.delay.Client$1.run(Client.java:31)
at java.lang.Thread.run(Thread.java:745)
示例 - 第三方資源響應時間長
第三方的資源有問題導致調用方響應時間長的話，和鎖等待的堆棧有點類似。
- 如果請求第三方為單線程則比較簡單，直接查看該線程的堆棧，如果每次抓堆棧信息都能看到在請求第三方資源的話，那說明就是有問題了，因為在響應時間很短的情況下，你不大可能每次都能抓到請求中的堆棧。
- 如果是多線程訪問的話，查看線程堆棧中是不是同時有很多線程同時在執(zhí)行這些操作，如果有，則需要考慮是不是第三方資源有問題了，同第一次條原因，在響應時間很短的情況下，能抓到很多線程都在執(zhí)行某一個操作，不太容易。
本文由郭軍營提供
2019年連續(xù)五十二天修心 土司于北京
