利用 Arthas 精准定位 Java 应用 CPU 负载太高问题

Arthas 官方社区正在举行征文活动，参加即有奖品拿哦~点击投稿

做者 | 张云翔

最近咱们线上有个应用服务器有点上头，CPU总能跑到99%，我寻思着它流量也不大啊，为啥能把本身整这么累？因而我登上这台服务器，看看它到底在干啥！

之前碰到相似问题，可能会考虑使用 top -Hp 加 jstack 命令去排查，虽然能大体定位到问题范围，但有效信息仍是太少了，多数时候仍是要靠猜。今天向你们推荐一款更高效更精准的工具：Arthas！Arthas 是 Alibaba 开源的 Java 诊断工具，可以帮助咱们快速定位线上问题。基本的安装使用能够参考官方文档：https://alibaba.github.io/arthas 

此次咱们利用它来排查 CPU 负载高的问题。CPU 负载太高通常是某个或某几个线程有问题，因此咱们尝试使用第一个命令：thread，这个命令会显示全部线程的信息，而且把 CPU 使用率高的线程排在前面。

[arthas@384]$ thread
Threads Total: 112, NEW: 0, RUNNABLE: 26, BLOCKED: 0, WAITING: 31, TIMED_WAITING: 55, TERMINATED: 0
ID  NAME    STATE    %CPU  TIME
108 h..ec-0 RUNNABLE  51   4011:48     
100 h..ec-2 RUNNABLE  48   4011:51
...

为了方便阅读，删掉了一些不重要的信息

能够看到，CPU 资源几乎被前两个线程占满，而且已经执行了 4000 多分钟，咱们服务器也就启动了两天，可见这两天它们是一刻也没闲着！那它们究竟在干什么呢？咱们可使用命令：thread id，查看线程堆栈。

[arthas@384]$ thread 108
"http-nio-7001-exec-10" Id=108 cpuUsage=51% RUNNABLE
    at c.g.c.c.HashBiMap.seekByKey(HashBiMap.java)
    at c.g.c.c.HashBiMap.put(HashBiMap.java:270)
    at c.g.c.c.HashBiMap.forcePut(HashBiMap.java:263)
    at c.y.r.j.o.OaInfoManager.syncUserCache(OaInfoManager.java:159)

也可使用 thread -n 3 命令打印出 CPU 占比最高的前三个线程，这差很少是 > top -Hp>  & > printf>  & > jstack>  三令合一的效果了>

能够看到，这个线程一直在执行 HashBiMap.seekByKey 方法（能够重复执行几回 thread id 确保该线程执行的方法没有时刻在变化），形成这个问题通常有两个缘由：

1. seekByKey 方法被循环调用
2. seekByKey 内部有死循环

先看一下是否是第一种，咱们使用 tt 命令监听一下这个方法的调用状况：

tt -t com.google.common.collect.HashBiMap seekByKey -n 100

注意：在线上执行这个命令的时候，必定要记得加上 -n 参数，不然线上巨大的流量可能会瞬间撑爆你的 JVM 内存执行结果显示，seekByKey 方法并无被一直调用，那大几率是 seekByKey 方法内部有死循环。看下这个方法内部的逻辑，咱们可使用 jad com.google.common.collect.HashBiMap seekByKey 命令反编译这个方法，这样作的好处是显得比较高端，不过我仍是打算直接找到源码，说不定还有注释。源码以下：

private BiEntry<K, V> seekByKey(@Nullable Object key, int keyHash) {
    for (BiEntry<K, V> entry = hashTableKToV[keyHash & mask];
        entry != null;
        entry = entry.nextInKToVBucket) {
      if (keyHash == entry.keyHash && Objects.equal(key, entry.key)) {
        return entry;
      }
    }
    return null;
  }

而后并无注释，还好这个方法逻辑比较简单，也很容易看懂。

1. 经过 hash 找到 bucket，每一个 bucket 是一个链表；
2. 遍历链表，找到这个 key 对应的 entry。这里要留意下 entry 的下一个节点是 nextInKToVBucket，后文中会用到。

发生了死循环，咱们猜测多是由于这个链表有环路。那么有没有办法验证这个猜测呢？答案是有！那么如何验证呢？首先咱们要得到这个 HashBiMap 对象，以便于查询对象里的数据。得到这个对象有不少办法，好比监听这个对象的某个方法，而后主动触发这个方法。这里向你们介绍一种更为通用的方法，这个方法在 SpringMVC 程序里很是好用。由于咱们是 SpringMVC 应用，全部请求都会被 RequestMappingHandlerAdapter 拦截，咱们经过 tt 命令，监听 invokeHandlerMethod 的执行，而后在页面随便点点，就会获得如下内容：

[arthas@384]$ tt -t org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter invokeHandlerMethod -n 10
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 622 ms.
 INDEX    COST(ms)      OBJECT        CLASS             METHOD
------------------------------------------------------------------------------------
 1000     481.203383    0x481eb705    RequestMappingHandlerAdapter    invokeHandlerMethod
 1001     3.432024      0x481eb705    RequestMappingHandlerAdapter    invokeHandlerMethod
...

tt 命令会记录方法调用时的全部入参和返回值、抛出的异常、对象自己等数据。INDEX 字段表明着一次调用，后续tt还有不少命令都是基于此编号指定记录操做。

咱们能够经过 -i 参数后边跟着对应的 INDEX 编号查看这条记录的详细信息。再经过 -w 参数，指定一个 OGNL 表达式，查找相关对象：

[arthas@384]$ tt -i 1000 -w 'target.getApplicationContext()'
@AnnotationConfigServletWebServerApplicationContext[
    reader=@AnnotatedBeanDefinitionReader[org.springframework.context.annotation.AnnotatedBeanDefinitionReader@50294e97],
    scanner=@ClassPathBeanDefinitionScanner[org.springframework.context.annotation.ClassPathBeanDefinitionScanner@5eeeaae2],
    annotatedClasses=@LinkedHashSet[isEmpty=true;size=0],
    basePackages=null,

OGNL 使用文档： https://commons.apache.org/proper/commons-ognl/language-guide.html

Arthas 会把当前执行的对象放到 target 变量中，经过 target.getApplicationContext() 就获得了 SpringContext 对象，而后，咱们就能够随心所欲了!

接下来咱们须要用 OGNL 写一个函数，来实现链表的环路检测，在 OGNL 里写一段环路检测代码里是不太容易的，这里我用了一个取巧的伪实现。

#loopCnt=0,
#foundCycle=:[ #this == null ? false :
    #loopCnt > 50 ? true :
        (
            #loopCnt = #loopCnt + 1,
            #foundCycle(#this.nextInKToVBucket)
        )]

由于我知道一个 bucket 不太可能有 50 个以上的节点，因此就经过遍历次数是否大于 50 来判断是否有环路。

完整的命令：

tt -i 1000 -w 'target.getApplicationContext().getBean("oaInfoManager").userCache.entrySet().{delegate}.{^ #loopCnt = 0,#foundCycle = :[ #this == null ? false : #loopCnt > 50 ? true : (#loopCnt = #loopCnt + 1, #foundCycle(#this.nextInKToVBucket))], #foundCycle(#this)}.get(0)' -x 2

命令解析：

1. 获取 HashBiMap 对象：target.getApplicationContext().getBean("oaInfoManager").userCache
2. 遍历全部 entry，取出第一个有环路的 entry
3. -x 参数指定展开层级，咱们须要将这个参数设置的比环要大一些，才能确保能够发现环路。这里咱们的环路很是小，因此设置成了 2

执行结果以下：

@BiEntry[
    key=@String[张三],
    value=@Long[1111],
    nextInKToVBucket=@BiEntry[
        key=@String[李四],
        value=@Long[2222],
        nextInKToVBucket=@BiEntry[张三=1111]
    ]
]

能够看到是有 张三->李四->张三 这样一个环路。至此，形成死循环的缘由肯定了下来。结合两个线程几乎同时启动，又同时在执行 HashBiMap.forcePut 方法，容易想到是由于并发致使了数据的不一致，这一点也能够验证，不过因为篇幅有限，这里就再也不赘述。找到了问题，就成功了 99%，解决这个问题的方法很是简单，就是对 syncUserCache 方法加一个 synchronized 关键字！

结语

此次遇到的问题并不复杂，用 jstack 命令也能够解决的了。但咱们但愿经过这样一个案例，向你们展现 Arthas 一些强大的功能，帮助你们打开思路，将来在遇到更复杂场景时，能够多一些趁手的工具！

Arthas 征文活动火热进行中

Arthas 官方正在举行征文活动，若是你有：

• 使用 Arthas 排查过的问题
• 对 Arthas 进行源码解读
• 对 Arthas 提出建议
• 不限，其它与 Arthas 有关的内容

  欢迎参加征文活动，还有奖品拿哦~点击投稿

“ 阿里巴巴云原生关注微服务、Serverless、容器、Service Mesh 等技术领域、聚焦云原生流行技术趋势、云原生大规模的落地实践，作最懂云原生开发者的公众号。”