前不久公司進行了一次大促，晚上值班。大促是從晚上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，這些也可以避免很多線上問題。