記一次CPU佔用率和load高的排查

　　前不久公司進行了一次大促，晚上值班。大促是從晚上8點多開始的，一開始流量慢慢的進來，觀察了應用的各項指標，一切都是正常的，由於這是雙11事後的第一次大促，想着用戶的購買慾應該不會太強，因此咱們的運維同事9點多就回家了在家裏面遠程支持，留下交易組和其它後端的技術值班，樓主就是交易組的。誰知10點整的時候咱們的前置服務器忽然告警，報資源佔用太高。以下圖：

   

　　說實話,load超過10仍是第一次見。。。。

　　我是第一個發現狀況的，因此我第一時間把告警信息發到羣上以後，而後通知運維jstack當時的線程堆棧。就直接登陸其中一臺服務器用top -c 命令查看佔用cpu最高命令的進程。發現是一個進程號爲19988的java進程。而後用top -Hp 命令查看下面的線程。而後記錄下來

      過了幾分鐘以後收到運維主管發過來的jstack的文件，一個66M的文件。。。。。

　　而後我用記錄下的線程ID去裏面查，竟然一個都沒找到。。。。 後面確認了運維發過的來jstack文件有信息缺失。。。。。

      而後看到羣上一些技術同事說問題多是調用IT部門的會員卡查詢忽然變慢了，響應時間由幾十ms變成5s，致使了線程數堆積。這裏說一下這個IT部門是咱們集團裏面的一個老部門和咱們部門是獨立的，我所在的部門是互聯網這一塊，IT部門相對來就是傳統的那種。IT的系統都是外包來作的，性能真的不敢恭維，已知某個系統的qps是3, 因此技術水平本身腦補。當時我看了一下cat監控，確實有不少查IT會員卡的超時告警，但這個狀況是一直都存在的，之前卻不會出現這種狀況。而且負責會員卡的用戶組同事說：他們已經對IT的接口加了限流，若是超時太多，就會限制調用IT的接口的次數，線程堆積的狀況應該是不存在的。當時分析了一下就算有不少這種等待io的線程，其現象也應該是load高，但cpu佔用率應該不是會過高的。這種cpu高和load高的狀況一種很常見的狀況就是頻繁的GC。我因而再回到cat上面去看監控指標，點heartbeat這一欄。對比各項指標，果真間發現GC的時間和次數在10點的時候忽然變多了。

 

　　嗯，問題應該是確認了。我因而在有問題機器查找對應的GC日誌：

 [GC (Allocation Failure) [PSYoungGen: 1321555K->7203K(1354752K)] 2182429K->881391K(4151296K), 0.0216324 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1317411K->6176K(1353216K)] 2191599K->882824K(4149760K), 0.0177299 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1316384K->7255K(1357824K)] 2193032K->885846K(4154368K), 0.0198454 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1323607K->6080K(1356288K)] 2202198K->886357K(4152832K), 0.0194745 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1279980K->117750K(1073152K)] 2366227K->1332344K(3869696K), 0.1398088 secs] [Times: user=0.51 sys=0.00, real=0.14 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1073142K->94600K(1176576K)] 2287736K->1409135K(3973120K), 0.1220951 secs] [Times: user=0.47 sys=0.00, real=0.13 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1049992K->105231K(1184256K)] 2364527K->1492688K(3980800K), 0.1323488 secs] [Times: user=0.45 sys=0.00, real=0.13 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1073935K->111730K(1182208K)] 2461392K->1563948K(3978752K), 0.1109970 secs] [Times: user=0.42 sys=0.00, real=0.11 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1080434K->81108K(1197568K)] 2532652K->1607799K(3994112K), 0.1113381 secs] [Times: user=0.42 sys=0.00, real=0.11 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1065684K->79209K(1184768K)] 2592375K->1654630K(3981312K), 0.1410440 secs] [Times: user=0.40 sys=0.00, real=0.14 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1063785K->75484K(1219584K)] 2639206K->1694154K(4016128K), 0.1043986 secs] [Times: user=0.39 sys=0.00, real=0.10 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1106652K->71290K(1209344K)] 2725322K->1727044K(4005888K), 0.0994654 secs] [Times: user=0.38 sys=0.00, real=0.10 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1102458K->74219K(1236480K)] 2758212K->1769216K(4033024K), 0.1000352 secs] [Times: user=0.38 sys=0.00, real=0.10 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1141227K->74573K(1228288K)] 2836224K->1809430K(4024832K), 0.1089653 secs] [Times: user=0.40 sys=0.00, real=0.11 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1141581K->70656K(1250816K)] 2876438K->1842238K(4047360K), 0.1406505 secs] [Times: user=0.38 sys=0.00, real=0.14 secs] 
 [GC (Allocation Failure) [PSYoungGen: 1168384K->95266K(1244672K)] 2939966K->1897805K(4041216K), 0.1442105 secs] [Times: user=0.40 sys=0.00, real=0.14 secs] 

　　果真看到了過了10點，堆內存的使用忽然暴漲，應用在頻繁的GC，而且每次GC時間基本都在100ms以上。至於具體是什麼緣由致使的GC如今還沒得知，惟一的辦法就是dump出當時內存鏡像，遺憾的是當時沒有及時的dump下來。CPU佔用率高和load高的狀況只持續了一分鐘時間，運維同事也沒有dump下來。

　　要找出緣由只能從當時的請求來入手，因而我看當時的應用請求狀況。發現GC的的時間點還真的和會員卡的請求忽然大量增長和超時基本吻合，因而我來拉下會員卡項目的代碼選了其中的會員卡列表和微信卡包列表等相關接口來看一下，還真的發現了一些的問題。其中比較重要的一個是：若是客戶端沒傳分頁傳參數進來程序就會load用戶全部數據出去，以前據說某些用戶下面有1000多張會員卡。而後我去看了請求日誌發現微信卡包列表的全部請求都沒有傳分頁參數進來，客戶端某些版本沒有傳。而且會員卡列表和微信卡包列表當請求量是平時的幾十倍。load用戶所有數據，請求量大，這種狀況引發GC的機率確實比較大。後面我把了解的狀況反饋給了用戶組的同事。

　　總結一下整個過程：從告警到問題定位，中間的幾個點實際上是能夠改進的。

　　一、jstack文件信息大多，但關鍵信息卻丟失了。緣由是jstack是10秒鐘才記錄一次，因此我記錄下來的線程ID和運維給的文件裏面的信息裏面並不必定對得上。運維同事最好能夠提供一下實時工具保留當時的第一手信息。另外若是有什麼好用的工具歡迎推薦~。

　　二、監控不到位。會員卡用的限流組件是阿里最新開源的Sentinel，採用的qps限流並非線程數限流。因此當時並不知道會員卡相關到底吃了系統多少線程。對於限流組件這塊我我的是比較推薦hystrix，由於功能比較齊全，開源時間長，不少坑別人都已經踩過了。阿里的Sentinel剛出來應該不少點還須要完善。另一點就是GC內存的文件沒有及時dump下來。

　　三、代碼規範和code-view。最好接入一些代碼檢查工具好比sonar，及時找出程序裏面一些坑。一些熱點代碼最好組織一下code-view，這些也能夠避免不少線上問題。