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遇到这种输入, 就爆掉了.
  4. 频繁的获取/释放锁 大量的锁操作 比如大量线程快速同步写 log 到 System.out/System.err (PrintStream).
  5. 频繁获取线程的 Stacktrace. 比如为了 profiling 频繁获取, 出错写 e.printStacktrace() 等操作.
  6. 很多线程都在忙于 压缩/解压缩 操作

对于上面第一种类型, 基本可以通过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里面的数据去验证.

对于第四种, 多次查看 thread dump, 就会发现频繁获取释放的锁.

对于第五种, 多次查看 thread dump, 有可能会看到, 或者看到特别多的出错写 log 的.

标签: none

添加新评论