日常問(wèn)題排查-調(diào)用超時(shí)

前言

日常Bug排查系列都是一些簡(jiǎn)單Bug排查，筆者將在這里介紹一些排查Bug的簡(jiǎn)單技巧，同時(shí)順便積累素材^_。

Bug現(xiàn)場(chǎng)

這次的Bug是大家喜聞樂(lè)見(jiàn)的調(diào)用超時(shí)。即A調(diào)用B超過(guò)了5s

搜索一下日志，發(fā)現(xiàn)A系統(tǒng)在發(fā)出5s后超時(shí)。B系統(tǒng)在將近8s后才收到請(qǐng)求，也就是說(shuō)B系統(tǒng)還沒(méi)開(kāi)始處理，A系統(tǒng)就超時(shí)了。

開(kāi)始排查

那么這5秒鐘時(shí)間到底消失在哪里呢？有3個(gè)可能的點(diǎn):

1)A日志打點(diǎn)到真正發(fā)出請(qǐng)求包
2)網(wǎng)絡(luò)上
3)B真正接收請(qǐng)求包到B日志打點(diǎn)。

網(wǎng)絡(luò)check

首先筆者檢查了當(dāng)時(shí)此機(jī)器的Net Traffic,發(fā)現(xiàn)非常平穩(wěn)，考慮不是網(wǎng)絡(luò)的鍋。

Full GC

對(duì)于Java應(yīng)用，第二個(gè)考慮的點(diǎn)應(yīng)該是GC,畢竟是Stop The World!筆者于是翻了下對(duì)應(yīng)
A/B系統(tǒng)兩臺(tái)
發(fā)現(xiàn)A系統(tǒng)okay,B系統(tǒng)在當(dāng)時(shí)有Full GC，而且長(zhǎng)達(dá)6s:

既然監(jiān)控到了，那么問(wèn)題基本就是B系統(tǒng)的Full GC了，這個(gè)長(zhǎng)達(dá)6s的full gc讓B系統(tǒng)5s后才打印出請(qǐng)求。可是這又引入了一個(gè)新的問(wèn)題，為什么一次Full GC能達(dá)到6s之巨。

為什么這么慢

觀察監(jiān)控，筆者發(fā)現(xiàn)Full GC有時(shí)候快有時(shí)候慢。翻出對(duì)應(yīng)6s的那條gc監(jiān)控日志。

B系統(tǒng)
[Full GC(Metadata GC Thresold) ...... (class unloading,5.5285249 secs]......[Times: user=0.85 sys=0.07 real=6.26 secs]
class unloading...

發(fā)現(xiàn)class unloading竟然會(huì)有將近5s。再進(jìn)一步用awk過(guò)濾，最高有10s的,最短有0.1s的，而他們回收的內(nèi)存大小確差不多。正常Full GC應(yīng)該不會(huì)有這么久,那個(gè)0.1s才感覺(jué)是正常的，難道當(dāng)時(shí)機(jī)器有什么事情發(fā)生?帶著疑問(wèn)，筆者繼續(xù)觀察監(jiān)控曲線，看看能不能找到些蛛絲馬跡,找到當(dāng)時(shí)的時(shí)間點(diǎn)，發(fā)現(xiàn):

GC慢的時(shí)候，對(duì)應(yīng)機(jī)器內(nèi)存的swap in很高。緊接著找了其它慢的Full GC。發(fā)現(xiàn)非常有規(guī)律，只要swap in很高Full GC就慢！
于是筆者，就嘗試著搜索了一下

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

發(fā)現(xiàn)，官方也發(fā)現(xiàn)了這個(gè)問(wèn)題，并給予了解釋。

為什么會(huì)有swap

實(shí)際上對(duì)應(yīng)機(jī)器的內(nèi)存使用率并不高，一共8G的內(nèi)存，JVM只占用到了4G左右。但swap的邏輯并僅僅是內(nèi)存吃緊了才使用swap分區(qū)。如果有一塊內(nèi)存長(zhǎng)期不用，也有可能被交換到swap分區(qū)。
例如，JVM的class信息，如果一個(gè)class MetaData僅僅是存在那里，并不被用到的話。
可能被kernel扔到swap里面。但這時(shí)候在GC可達(dá)性分析的時(shí)候，又會(huì)去訪問(wèn)這個(gè)MetaData信息，就導(dǎo)致雖然內(nèi)存利用率不高，但依舊發(fā)生使用swap導(dǎo)致慢的情況！

但是swap里面到底是什么內(nèi)容，是不是和jvm相關(guān)就很難知曉了。所以看上去是概率上出現(xiàn)GC慢的問(wèn)題。

另一個(gè)機(jī)房沒(méi)出問(wèn)題

這時(shí)候巧的是，業(yè)務(wù)開(kāi)發(fā)向筆者反映，另一個(gè)機(jī)房的相同應(yīng)用確不會(huì)出現(xiàn)此問(wèn)題。撈了下對(duì)應(yīng)日志，發(fā)現(xiàn)其class unloading只有0.9s左右。筆者觀察了下，發(fā)現(xiàn)另一個(gè)機(jī)房的機(jī)器并沒(méi)有用swap。于是筆者比較了一下兩個(gè)機(jī)房關(guān)于swap相關(guān)的內(nèi)核參數(shù):

GC慢機(jī)器 cat /proc/sys/vm/swappiness 60
GC正常機(jī)器 cat /proc/sys/vm/swappiness 1

發(fā)現(xiàn)我們新建機(jī)房的,我們SA已經(jīng)預(yù)先把swappiness調(diào)成了1，意思是告訴kernel盡量不要使用swap，這樣就不會(huì)有這種swap導(dǎo)致的坑爹問(wèn)題了。

總結(jié)

對(duì)于非內(nèi)存瓶頸的應(yīng)用，我們應(yīng)該基于實(shí)際情況決定是否把swap禁用掉，以免因swap造成卡頓！另外，
對(duì)于一個(gè)偶發(fā)性的問(wèn)題，我們應(yīng)該通過(guò)監(jiān)控等手段去尋找規(guī)律，這樣就很容易找到突破點(diǎn)。