從應用到內核查接口超時（上）

問題

---

以前的博文中說過最近在查一個問題，花費了近兩個星期，問題算是有了一個小結，是時候總結一下了。

排查過程走了不少彎路，因爲眼界和知識儲備問題，也進入了一些思惟誤區，但願此問題能之後再查詢此類問題時能有所警示和參考；並且不少排查方法和思路都來自於部門 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。

1. 儘可能分析更多的問題 case。找出他們的共性，避免盯錯問題點。好比這次問題排查開始時，若是多看幾個 case 就會發現，日誌停頓在任何日誌點都會出現，由此就能夠直接排除掉 HttpClient 和 Hystrix 的影響。
2. 在可控的環境復現問題。在測試環境復現問題可能幫助咱們隨時調整排查策略，極大地縮短排查週期。固然還須要注意的是必定要跟線上環境保持一致，不一致的環境極可能把你的思路帶歪，好比我在壓測復現問題時，因爲堆內存設置得過小，致使頻繁發生 GC，讓我錯認爲是 GC 緣由致使的停頓。
3. 對比變化，提出猜測。在服務出現問題時，咱們老是先問最近上線了什麼內容，程序是有慣性的，若是沒有變化，系統通常會一直正常運行。固然變化不止是時間維度上的，咱們還能夠在多個服務之間對比差別。
4. 排除法定位問題。通常咱們會提出多個致使問題的可能性，排查時，保持一個變量在變化，再對比問題的發生，從而總結出變量對問題的影響。
5. 解決。當咱們定位到問題以後，問題的解決通常都很簡單，可能只須要改一行代碼。

固然還有一個很是重要的點，貫穿始末，那就是 數據支持，排查過程當中必定要有數據做爲支持。經過總量、百分比數據的先後對比來講服其餘人相信你的理論，也就是用數聽說話。

關於本文有什麼疑問能夠在下面留言交流，若是您以爲本文對您有幫助，歡迎關注個人 微博 或 GitHub 。您也能夠在個人 博客REPO 右上角點擊 Watch 並選擇 Releases only 項來 訂閱 個人博客，有新文章發佈會第一時間通知您。