Arthas排查线上服务器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

排查步骤如下

1. 使用top命令观察CPU占用高的进程
   

2. 根据进程ID进一步查看占用线程

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

   

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

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

4. 使用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代码中去查看该行代码…
   

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

阿里Arthas

阿里Arthas号称Bug排查利器，功能非常强大，此文我不做过多介绍，后续有时间单独拎一篇文章对其详细讲解。
这里，我只用到了2个命令就能定位到错误问题代码位置。

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

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

2. 授予执行权限

     $ chmod 755 ./arthas-boot.jar
   

3. 使用生产服务采用同一用户启动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
   

4. 选择对应的生产服务
   这里我需要调试第二个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
   
   

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

     [arthas@8349]$ thread
   

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

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

6. 打印出线程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任务锁，第一次执行，在进入到方法后进行了死循环，导致一直没有打印结束日志

7. 到此，我们继续回到项目代码中，找到MarketWeightServiceImpl的154行
   

   一般造成CPU过高的原因大多数是死循环，通过这个思路，其实我们可以看出，假定业务逻辑没有问题的情况下，这里的单break并不能跳出双层循环

8. 问题定位到了，改造代码
   

9. 提交至master，通过jenkins再次发布生产环境
   通过观察生产环境的CPU，未再次发现问题，业务正常运转

总结

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

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