Java 程序中导致CPU 100%的常见原因与诊断思路

原文链接

上周某团队的某个业务的新功能1%上线, 上线不到1天, 开发人员发现该流程里下游有个应用不断有服务器挂掉, 症状表现为CPU 100%, 不能处理新请求. 为了临时快速解决该问题, 同事先是做了2个 heap dump 和 2个 CPU 在某个interval的usage的截屏, 然后让开发人员关闭该新功能, 同时下游服务器被完全重启一遍. 问题得以解决.

问题虽然被临时解决, 但是当时却没发现最终问题所在. 事后去查看相关log, 发现某些机器竟然在那个时间段, 没有把log发到中心log 服务器, 同时本地的某些log被覆盖. 根据截屏的 CPU usage, 发现有很多线程在当时在cache中查找某些值, 有几个线程在HashMap中get()某个值, 看上去很像HashMap的死循环问题, 可是另外有些花费很多CPU的线程又没在HashMap里面. 不过最终查看这些线程Stack, 确定问题是业务逻辑里面有如下代码:

TreeNode curNode = curNode.getParentNode();
Integer curVal = null;
while (null != curNode && null == curVal) {
    curVal = getSomeValueFromConfigCache(curNode);
}

仔细一看, 上面的代码是有问题的, 看上去哪些Node 是一个Tree 结构, 如果通过当前Node 查不到,就根据Parent去查, 结果这个逻辑里面并没有把向上替换的逻辑放到 while 循环里面. 根据当前的代码, 如果当前Node 查不到返回null, 那么这个while 就是一个死循环了. 所以改正很简单, 但是这个代价有点大. 测试代码可能99%都是当前Node 都能查到结果的, 可是就是有1%的数据, 可能要向上找到 ParentNode 才能查到.

对于这种导致CPU 100%的问题, 我们常见的有以下这几种:

1. Java 内存不够或溢出导致GC overhead问题, GC overhead 导致的CPU 100%问题;
2. 死循环问题. 如常见的HashMap被多个线程并发使用导致的死循环, 或者上面例子中的死循环;
3. 某些特费CPU的操作被长期执行. 以前有个case, 使用正则表达式去判断是不是符合某个规则, 可是有些时候输入参数是一个几十K或更长的数据, 该正则写又不好, 导致CPU遇到这种输入, 就爆掉了.

对于上面第一种类型, 基本可以通过GC overhead 的比例去看, 这种情况下CPU完全是GC 引起的, GC overhead 基本接近100%, 然后下一步就是做 heap dump, 去分析verbose GC log 和 heap dump;

对于上面第二种, 可以多次做CPU usage分析, 比如每次都是1s的interval 内所有线程消耗CPU的百分比, 因为CPU 已经100%, 所以很容易可以看到是哪些线程在大量消耗CPU, 然后去分析这些stacktrace, 基本上死循环的代码之外的stack每次都一样, 死循环以内的某些时候的stack有些差别. 可以通过结合 heap dump 里面的局部变量, 参数同时阅读stack里面的方法的调用关系, 去查看死循环的位置所在. 对于HashMap这种, 基本在几次tread dump中就能确定, 然后去 heap dump 去找到那个循环.

对于第三种, 基本和第二种一样, 首先观察下stack里面有没有看上去就是特耗CPU的操作, 如果有继续看源代码去查看. 最后结合heap dump里面的数据去验证.