记一次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，这些也能够避免不少线上问题。