記一次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的概率確實比較大。后面我把了解的情況反饋給了用戶組的同事。

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

　　1、jstack文件信息大多，但關鍵信息卻丟失了。原因是jstack是10秒鍾才記錄一次，所以我記錄下來的線程ID和運維給的文件里面的信息里面並不一定對得上。運維同事最好可以提供一下實時工具保留當時的第一手信息。另外如果有什么好用的工具歡迎推薦~。

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

　　3、代碼規范和code-view。最好接入一些代碼檢查工具比如sonar，及時找出程序里面一些坑。一些熱點代碼最好組織一下code-view，這些也可以避免很多線上問題。