日常問題排查 - 調用超時

前言

=====

日常 Bug 排查系列都是一些簡單 Bug 排查，筆者將在這裏介紹一些排查 Bug 的簡單技巧，同時順便積累素材 ^_^。

Bug 現場

這次的 Bug 是大家喜聞樂見的調用超時。即 A 調用 B 超過了 5s

搜索一下日誌，發現 A 系統在發出 5s 後超時。B 系統在將近 8s 後才收到請求，也就是說 B 系統還沒開始處理，A 系統就超時了。

開始排查

那麼這 5 秒鐘時間到底消失在哪裏呢？有 3 個可能的點:

1)A日誌打點到真正發出請求包

2)網絡上

3)B真正接收請求包到B日誌打點。

網絡 check

首先筆者檢查了當時此機器的 Net Traffic, 發現非常平穩，考慮不是網絡的鍋。

Full GC

對於 Java 應用，第二個考慮的點應該是 GC, 畢竟是 Stop The World! 筆者於是翻了下對應

A/B 系統兩臺

發現 A 系統 okay,B 系統在當時有 Full GC，而且長達 6s:

既然監控到了，那麼問題基本就是 B 系統的 Full GC 了，這個長達 6s 的 full gc 讓 B 系統 5s 後纔打印出請求。可是這又引入了一個新的問題，爲什麼一次 Full GC 能達到 6s 之巨。

爲什麼這麼慢

觀察監控，筆者發現 Full GC 有時候快有時候慢。翻出對應 6s 的那條 gc 監控日誌。

B系統

[Full GC(Metadata GC Thresold) ...... (class unloading,5.5285249 secs]......[Times: user=0.85 sys=0.07 real=6.26 secs]

class unloading...

發現 class unloading 竟然會有將近 5s。再進一步用 awk 過濾，最高有 10s 的, 最短有 0.1s 的，而他們回收的內存大小確差不多。正常 Full GC 應該不會有這麼久, 那個 0.1s 才感覺是正常的，難道當時機器有什麼事情發生? 帶着疑問，筆者繼續觀察監控曲線，看看能不能找到些蛛絲馬跡, 找到當時的時間點，發現:

GC 慢的時候，對應機器內存的 swap in 很高。緊接着找了其它慢的 Full GC。發現非常有規律，只要 swap in 很高 Full GC 就慢！

於是筆者，就嘗試着搜索了一下

https://blogs.oracle.com/poonam/long-class-unloading-pauses-with-jdk8

發現，官方也發現了這個問題，並給予瞭解釋。

爲什麼會有 swap

實際上對應機器的內存使用率並不高，一共 8G 的內存，JVM 只佔用到了 4G 左右。但 swap 的邏輯並僅僅是內存喫緊了才使用 swap 分區。如果有一塊內存長期不用，也有可能被交換到 swap 分區。

例如，JVM 的 class 信息，如果一個 class MetaData 僅僅是存在那裏，並不被用到的話。

可能被 kernel 扔到 swap 裏面。但這時候在 GC 可達性分析的時候，又會去訪問這個 MetaData 信息，就導致雖然內存利用率不高，但依舊發生使用 swap 導致慢的情況！

但是 swap 裏面到底是什麼內容，是不是和 jvm 相關就很難知曉了。所以看上去是概率上出現 GC 慢的問題。

另一個機房沒出問題

這時候巧的是，業務開發向筆者反映，另一個機房的相同應用確不會出現此問題。撈了下對應日誌，發現其 class unloading 只有 0.9s 左右。筆者觀察了下，發現另一個機房的機器並沒有用 swap。於是筆者比較了一下兩個機房關於 swap 相關的內核參數:

GC慢機器 cat /proc/sys/vm/swappiness 60

GC正常機器 cat /proc/sys/vm/swappiness 1

發現我們新建機房的, 我們 SA 已經預先把 swappiness 調成了 1，意思是告訴 kernel 儘量不要使用 swap，這樣就不會有這種 swap 導致的坑爹問題了。

總結

對於非內存瓶頸的應用，我們應該基於實際情況決定是否把 swap 禁用掉，以免因 swap 造成卡頓！另外，

對於一個偶發性的問題，我們應該通過監控等手段去尋找規律，這樣就很容易找到突破點。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/OptT-82hmkIDpirPt5kmrA