一次 Log4j2 日誌停頓問題的排查
問題
之前的博文中說過最近在查一個問題，花費了近兩個星期，問題算是有了一個小結，是時候總結一下了。
排查過程走了很多彎路，由於眼界和知識儲備問題，也進入了一些思維誤區，希望此問題能以後再查詢此類問題時能有所警示和參考；而且很多排查方法和思路都來自於部門 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()方法，日誌輸出需要將各種字符集的日誌都轉換為 byte 陣列，在進行大日誌輸出時，需要分塊進行。為了避免多執行緒塊之間的亂序，使用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 原因導致的停頓。
- 對比變化，提出猜想。在服務出現問題時，我們總是先問最近上線了什麼內容，程式是有慣性的，如果沒有變化，系統一般會一直正常執行。當然變化不止是時間維度上的，我們還可以在多個服務之間對比差異。
- 排除法定位問題。一般我們會提出多個導致問題的可能性，排查時，保持一個變數在變化，再對比問題的發生，從而總結出變數對問題的影響。
- 解決。當我們定位到問題之後，問題的解決一般都很簡單，可能只需要改一行程式碼。
當然還有一個非常重要的點，貫穿始末，那就是 資料支援 ，排查過程中一定要有資料作為支援。通過總量、百分比資料的前後對比來說服其他人相信你的理論，也就是用資料說話。
關於本文有什麼疑問可以在下面留言交流，如果您覺得本文對您有幫助，歡迎關注我的微博 或 ofollow,noindex" target="_blank">GitHub 。