线上服务器CPU100%的真相排查(Bug利器Arthas)

这起CPU100%的事故，由某个客户演示的bug暴露出来，气氛比较尴尬....

今日下午，因给业务部门演示一个小功能点的使用，由于该功能数据异常未能达到预期效果，而终止了演示，并且叫开发人员进行数据的可靠性进行自查，同时回到工位后的我也打开了电脑去查看数据，发现数据并未被定时跑批或是跑批终止，于是上线拉取关键日志，原定15分钟定时执行的任务，却并没有执行。难道是定时任务出问题了？

项目背景

由于是单体应用部署多个节点，并没有使用XXL-JOB这种，为了控制定时任务多节点只能一次执行，采用了SchedulerLock的方式（基于分布式锁）来实现定时任务的执行。

一开始怀疑Redis分布式锁出现了死锁问题，导致定时任务无法抢占到锁资源，没有执行定时任务，但在我观察了分布式锁后，发现并没有问题，而且这个方案已经上线2个多月，如果有问题早发生了。此时我观察了下生产2台服务器的CPU，均达到了100%，此时我知道大概率是代码存在死循环了，为了搞清真相，开始排查问题原因。

这里我采用2种方式去排查

jstack命令（网上非常多的吹牛案例均采用此方案）
Arthas工具（阿里开源诊断工具）

** 定时任务代码如下，此处代码并无问题 **

	/**
     * 潜客分配每15分钟执行一次
     *
     * lockAtMostFor：最长释放时间
     * lockAtLeastFor：拥有锁的最小时间
     */
    @Scheduled(cron = "0 0/15 * * * ?")
    @SchedulerLock(name = "startDistribution", lockAtMostFor = "20M", lockAtLeastFor = "12M")
    public void startDistribution() throws Exception {
    	log.info("【分配潜客名单】开始执行");
    	//业务代码
        log.info("【分配潜客名单】执行结束");
    }

Jstack

排查步骤如下

使用top命令观察CPU占用高的进程
根据进程ID进一步查看占用线程

# 命令：top -H -p PID
$ top -H -p 1379

3. 将线程ID转换为16进制串输出（用于抓取线程ID堆栈信息）

# 命令 printf "%x\n" 线程ID 
$ printf "%x\n" 1449
5a9

使用jstack命令抓取堆栈信息（利用16进制）

# 命令：jstack 进程ID | grep 线程ID16进制 -A行数
$ jstack 1379 | grep 5a9 -A90

输出结果：

[tfuser@web01 root]$ jstack 1379 | grep 5a9 -A90
"Job-Thread-3" #29 prio=5 os_prio=0 tid=0x00007f6ec6aee000 nid=0x5a9 runnable [0x00007f6e351f5000]
   java.lang.Thread.State: RUNNABLE
    at com.tifang.market.service.impl.MarketWeightServiceImpl.startDistribution(MarketWeightServiceImpl.java:154)
    at com.tifang.market.service.impl.MarketWeightServiceImpl$$FastClassBySpringCGLIB$$3b5113e6.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:684)
    at com.tifang.market.service.impl.MarketWeightServiceImpl$$EnhancerBySpringCGLIB$$53eb6d9c.startDistribution(<generate
    at com.tifang.core.quartz.MarketWeightTask.startDistribution(MarketWeightTask.java:62)
    at com.tifang.core.quartz.MarketWeightTask$$FastClassBySpringCGLIB$$d4f16575.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor$$Lambda$806/1180241420.call(U
    at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:73)
    at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLo
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
    at com.tifang.core.quartz.MarketWeightTask$$EnhancerBySpringCGLIB$$cceb1e7a.startDistribution(<generated>)
    at sun.reflect.GeneratedMethodAccessor3355.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)

到此，我们已经获取到了详细的信息，此时我们应该转场到Java代码中去查看该行代码...

其实代码中俨然已经存在了问题，不知道大家能不能一眼看出，接下来我们再用神器Arthas来排查

阿里Arthas

阿里Arthas号称Bug排查神器，功能非常强大，此文我不做过多介绍，后续有时间单独拎一篇文章对其详细讲解。

这里，我只用到了2个命令就能定位到错误问题代码位置。

在服务器上下载arthas-boot.jar

$ wget https://arthas.gitee.io/arthas-boot.jar

授予执行权限

$ chmod 777 ./arthas-boot.jar

使用生产服务采用同一用户启动arthas，并选择对应的生产服务

$ java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.3.9
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
  * [1]: 1944 /data/app/tfteacher/tfteacher.jar
  [2]: 8349 /data/app/tfoaserver/tfoaserver.jar

选择对应的生产服务这里我需要调试第二个java服务，所以我输入2，接下来会进入到arthas的用户进程命令中

2
[INFO] local lastest version: 3.3.9, remote lastest version: 3.4.0, try to download from remote.
[INFO] Start download arthas from remote server: https://arthas.aliyun.com/download/3.4.0?mirror=aliyun
[INFO] Download arthas success.
[INFO] arthas home: /home/tfuser/.arthas/lib/3.4.0/arthas
[INFO] Try to attach process 8349
[INFO] Attach process 8349 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          

wiki      https://arthas.aliyun.com/doc                                         
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html                   
version   3.4.0                                                                 
pid       8349                                                                  
time      2020-09-03 21:09:41                                                   

[arthas@8349]$  //此处的用户发生变化，变为了arthas

重点来了，这里我输入thread来查看当前服务的线程情况

[arthas@8349]$ thread

可以看到，上图ID为22的线程，占用着99%的CPU资源，并且已经持续运行654分钟，太吓人了，10多个小时了

此处可以输入很多命令，详见arthas教程

打印出线程ID为22的详细信息，看看究竟干了什么见不得人的事

[arthas@8349]$ thread 22
"Job-Thread-1" Id=22 RUNNABLE
  at com.tifang.market.service.impl.MarketWeightServiceImpl.startDistribution(MarketWeightServiceImpl.java:154)
  at com.tifang.market.service.impl.MarketWeightServiceImpl$$FastClassBySpringCGLIB$$3b5113e6.invoke(<generated>)
  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
  at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:684)
  at com.tifang.market.service.impl.MarketWeightServiceImpl$$EnhancerBySpringCGLIB$$48c8daec.startDistribution(<generated>)
  at com.tifang.core.quartz.MarketWeightTask.startDistribution(MarketWeightTask.java:62)
  at com.tifang.core.quartz.MarketWeightTask$$FastClassBySpringCGLIB$$d4f16575.invoke(<generated>)
  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)

再结合日志文件进行排查，但只有开始日志，没有结束日志，日志抓取输出如下：

$ grep -A 20 -B 10 -i "分配潜客名单】" info.log

该项目是10:00~22:00执行，每15分钟执行一次，初步估计10:45是该节点第一次获取到redis任务锁，第一次执行，在进入到方法后进行了死循环，导致一直没有打印结束日志

到此，我们继续回到项目代码中，找到MarketWeightServiceImpl的154行一般造成CPU过高的原因大多数是死循环，通过这个思路，其实我们可以看出，假定业务逻辑没有问题的情况下，这里的单break并不能跳出双层循环
问题定位到了，改造代码
提交至master，通过jenkins再次发布生产环境通过观察生产环境的CPU，未再次发现问题，业务正常运转

总结

好在这个事故并没有影响到其他业务的正常运转，修复后单独找了写这个代码的开发同学，作为技术leader，对于代码质量问题有不可推卸的责任，但同时也需要组织技术人员开一个事故会议来严肃处理这个事，奇怪的是阿里云也没有CPU报警或运维人员没有关注，CodeReview人员也并没有关注到这个问题，这都是团队不足之处，虽说这次没有造成生产故障，但是下次、下下次呢？每一个细节点都需要我们要去注意，去揣摩，去完善...

希望此文能够对开发人员有一定的帮助，并且Arthas确实是个好东西，接下来我们详细聊聊这个神器【9.3日午夜更】

另外收到笔记本、水杯、和鼠标垫啦.... 感谢优弧