线上服务器CPU100% jstack+Arthas排查

原文：https://juejin.cn/post/6868312926453760013

项目背景

由于是单体应用部署多个节点，并没有使用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
复制代码
  1. 使用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代码中去查看该行代码...

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

阿里Arthas

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

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

  1. 在服务器上下载arthas-boot.jar
$ wget https://arthas.gitee.io/arthas-boot.jar
复制代码
  1. 授予执行权限
$ chmod 777 ./arthas-boot.jar
复制代码
  1. 使用生产服务采用同一用户启动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
复制代码
  1. 选择对应的生产服务 这里我需要调试第二个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
复制代码
  1. 重点来了，这里我输入thread来查看当前服务的线程情况
[arthas@8349]$ thread
复制代码

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

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

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

  1. 到此，我们继续回到项目代码中，找到MarketWeightServiceImpl的154行 一般造成CPU过高的原因大多数是死循环，通过这个思路，其实我们可以看出，假定业务逻辑没有问题的情况下，这里的单break并不能跳出双层循环

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

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


作者：君哥聊编程
链接：https://juejin.cn/post/6868312926453760013
来源：稀土掘金
著作权归作者所有。商业转载请联系作者获得授权，非商业转载请注明出处。
posted @ 2022-12-02 10:16  这个名字想了很久~  阅读(392)  评论(0)  编辑  收藏  举报