問題
之前的博文中說過最近在查一個問題，花費了近兩個星期，問題算是有了一個小結，是時候總結一下了。
排查過程走了很多彎路，由于眼界和知識儲備問題，也進入了一些思維誤區，希望此問題能以後再查詢此類問題時能有所警示和參考；而且很多排查方法和思路都來自于部門 leader 和 組裡大神給的提示和啟發，總結一下也能對這些知識有更深的了解。
這個問題出現在典型的高并發場景下，現象是某個接口會偶爾逾時，查了幾個 case 的日志，發現 httpClient 在請求某三方接口結束後輸出一條日志時間為 A，方法傳回後将請求結果解析成為 JSON 對象後，再輸出的日志時間為 B， AB之間的時間差會特别大，100-700ms 不等，而 JSON 解析正常是特别快的，不應該超過 1ms。
轉載随意，文章會持續修訂，請注明來源位址：https://zhenbianshu.github.io 。
GC
首先考慮導緻這種現象的可能：
- 應用上有鎖導緻方法被 block 住了，但 JSON 解析方法上并不存在鎖，排除這種可能。
- JVM 上，GC 可能導緻 STW。
- 系統上，如果系統負載很高，作業系統繁忙，線程排程出現問題可能會導緻這種情況，但觀察監控系統發現系統負載一直處于很低的水準，也排除了系統問題。
我們都知道 JVM 在 GC 時會導緻 STW，進而導緻所有線程都會暫停，接下來重點排查 GC 問題。
首先我們使用 jstat 指令檢視了 GC 狀态，發現 fullGC 并不頻繁，系統運作了兩天才有 100 來次，而 minorGC 也是幾秒才會進行一次，且 gcTime 一直在正常範圍。
由于我們的 JVM 在啟動時添加了
-XX:+PrintGCApplicationStoppedTime
參數，而這個參數的名字跟它的意義并不是完全相對的，在啟用此參數時，gclog 不僅會列印出 GC 導緻的 STW，其他原因導緻的 STW 也會被記錄到 gclog 中，于是 gclog 就可以成為一個重要的排查工具。
檢視 gclog 發現确實存在異常狀況，如下圖：
系統 STW 有時會非常頻繁地發生，且持續時間也較長，其中間隔甚至不足 1ms，也就是說一次停頓持續了幾十 ms 之後，系統還沒有開始運作，又會進行第二次 STW，如上圖的情況，系統應該會一次 hang 住 120ms，如果次數再頻繁一些，确實有可能會導緻接口逾時。
安全點和偏向鎖
安全點日志
那麼這麼頻繁的 STW 是由什麼産生的呢，minorGC 的頻率都沒有這麼高。
我們知道，系統在 STW 前，會等待所有線程安全點，在
安全點
裡，線程的狀态是确定的，其引用的 heap 也是靜止的，這樣，JVM 才能安心地進行 GC 等操作。至于安全點的常見位置和安全點的實作方式網卡有很多文章介紹這裡不再多提了，這裡重點說一下安全點日志。
安全點日志是每次 JVM 在所有線程進入安全點 STW 後輸出的日志，日志記錄了進入安全點用了多久，STW 了多久，安全點内的時間都是被哪個步驟消耗的，通過它我們可以分析出 JVM STW 的原因。
服務啟動時，使用
-XX:+UnlockDiagnosticVMOptions -XX:+PrintSafepointStatistics -XX:+LogVMOutput -XX:LogFile=./safepoint.log
參數，可以将安全點日志輸出到 safepoint.log 中。
在安全點日志中，我發現有很多下圖類似的日志輸出：
從前面的 vmopt 列可以得知，進入安全點的原因是
RevokeBias
， 查資料得知，這是在釋放
偏向鎖
。
偏向鎖
偏向鎖是 JVM 對鎖的一種優化，JVM 的開發人員統計發現絕大部分的鎖都是由同一個線程擷取，鎖争搶的可能性很小，而系統調用一次加鎖釋放鎖的開銷相對很大，是以引入偏向鎖預設鎖不會被競争，偏向鎖中的 “偏向” 便指向第一個擷取到鎖的線程。在一個鎖在被第一次擷取後，JVM 并不需要用系統指令加鎖，而是使用偏向鎖來标志它，将對象頭中 MarkWord 的偏向鎖辨別設定為1，将偏向線程設定為持續鎖的線程 ID，這樣，之後線程再次申請鎖時如果發現這個鎖已經 “偏向” 了目前線程，直接使用即可。而且持有偏向鎖的線程不會主動釋放鎖，隻有在出現鎖競争時，偏向鎖才會釋放，進而膨脹為更進階别的鎖。
有利則有弊，偏向鎖在單線程環境内确實能極大降低鎖消耗，但在多線程高并發環境下，線程競争頻繁，而偏向鎖在釋放時，為了避免出現沖突，需要等到進入全局安全點才能進行，是以每次偏向鎖釋放會有更大的消耗。
明白了 JVM 為什麼會頻繁進行 STW，再修改服務啟動參數，添加
-XX:-UseBiasedLocking
參數禁用偏向鎖後，再觀察服務運作。
發現停頓問題的頻率下降了一半，但還是會出現，問題又回到原點。
Log4j
定位
這時候就需要猜想排查了。首先提出可能導緻問題的點，再依次替換掉這些因素壓測，看能否複現來确定問題點。
考慮到的問題點有
HttpClient、Hystrix、Log4j2
。使用固定資料替換了三方接口的傳回值，删去了 Hystrix，甚至将邏輯代碼都删掉，隻要使用 Log4j2 輸出大量日志，問題就可以複現，終于定位到了 Log4j2，原來是監守自盜啊。。
雖然定位到 Log4j2，但日志也不能不記啊，還是要查問題到底出在哪裡。
使用 btrace 排查 log4j2 内的鎖性能。
首先考慮 Log4j2 代碼裡的鎖，懷疑是由于鎖沖突，導緻輸出 log 時被 block 住了。
檢視源碼，統計存在鎖的地方有三處：
-
rollover()
-
encodeText()
synchronized
-
flush()
具體是哪一處代碼出現了問題呢，我使用
btrace
這一 Java 性能排查利器進行了排查。
使用 btrace 分别在這三個方法前後都注入代碼，将方法每次的執行時間輸出，然後進行壓測，等待問題發生，最終找到了執行慢的方法:
encodeText()
排查代碼并未發現 encodeText 方法的異常（千錘百煉的代碼，當然看不出什麼問題）。
使用 jmc 分析問題
這時，組内大神建議我使用 jmc 來捕捉異常事件。 給 docker-compose 添加以下參數來啟用環境的 JFR。
environment:
- JFR=true
- JMX_PORT=port
- JMX_HOST=ip
- JMX_LOGIN=user:pwd
在記錄内查找停頓時間附近的異常事件，發現耗時統計内有一項長耗時引人注目，調用
RandomAccessFile.write()
方法竟然耗時 1063 ms，而這個時間段和線程 ID 則完全比對。
檢視這個耗時長的方法，它調用的是 native 方法
write()
。。。
native 方法再查下去就是系統問題了，不過我比較懷疑是 docker 的問題，會再接着排查，等有結論了再更新。
解決
問題總是要解決的，其實也很簡單：
- 服務少記一些日志，日志太多的話才會導緻這個問題。
- 使用 Log4j2 的異步日志，雖然有可能會在緩沖區滿或服務重新開機時丢日志。
小結
查問題的過程确實學習到了很多知識，讓我更熟悉了 Java 的生态，但我覺得更重要的是排查問題的思路，于是我總結了一個排查問題的一般步驟，當作以後排查此類問題的 checkList。
- 盡量分析更多的問題 case。找出他們的共性，避免盯錯問題點。比如此次問題排查開始時，如果多看幾個 case 就會發現，日志停頓在任何日志點都會出現，由此就可以直接排除掉 HttpClient 和 Hystrix 的影響。
- 在可控的環境複現問題。在測試環境複現問題可能幫助我們随時調整排查政策，極大地縮短排查周期。當然還需要注意的是一定要跟線上環境保持一緻，不一緻的環境很可能把你的思路帶歪，比如我在壓測複現問題時，由于堆記憶體設定得太小，導緻頻繁發生 GC，讓我錯認為是 GC 原因導緻的停頓。
- 對比變化，提出猜想。在服務出現問題時，我們總是先問最近上線了什麼内容，程式是有慣性的，如果沒有變化，系統一般會一直正常運作。當然變化不止是時間次元上的，我們還可以在多個服務之間對比差異。
- 排除法定位問題。一般我們會提出多個導緻問題的可能性，排查時，保持一個變量在變化，再對比問題的發生，進而總結出變量對問題的影響。
- 解決。當我們定位到問題之後，問題的解決一般都很簡單，可能隻需要改一行代碼。
當然還有一個非常重要的點，貫穿始末，那就是
資料支援
，排查過程中一定要有資料作為支援。通過總量、百分比資料的前後對比來說服其他人相信你的理論，也就是用資料說話。
關于本文有什麼疑問可以在下面留言交流，如果您覺得本文對您有幫助，歡迎關注我的 微網誌 或 GitHub 。您也可以在我的 部落格REPO 右上角點選
Watch
并選擇
Releases only
項來
訂閱
我的部落格，有新文章釋出會第一時間通知您。