今日下午，因给业务部门演示一个小功能点的使用，由于该功能数据异常未能达到预期效果，而终止了演示，并且叫开发人员进行数据的可靠性进行自查，同时回到工位后的我也打开了电脑去查看数据，发现数据并未被定时跑批或是跑批终止，于是上线拉取关键日志，原定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将线程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，未再次发现问题，业务正常运转
总结
以上只是使用arthas最基础的功能进行线上问题排查，arthas还有很多功能强大的指令供我们使用。在没有arthas之前，我们只能使用jvm提供的指令进行排查，过程复杂很容易错过生产事故的第一现场，arthas的出现极大的提升问题排查的效率，但arthas也有不足的地方，对于tomcat的web服务监听似乎就比较局限了。
