日常問題排查-調用超時
前言
日常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造成卡頓！另外，
對於一個偶發性的問題，我們應該通過監控等手段去尋找規律，這樣就很容易找到突破點。
