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日午夜更】

  • 5
    点赞
  • 13
    收藏
  • 打赏
    打赏
  • 2
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
©️2022 CSDN 皮肤主题:大白 设计师:CSDN官方博客 返回首页
评论 2

打赏作者

君哥聊编程

你的鼓励将是我创作的最大动力

¥2 ¥4 ¥6 ¥10 ¥20
输入1-500的整数
余额支付 (余额:-- )
扫码支付
扫码支付:¥2
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值