一次 CPU 飙高异常的处理

一次 CPU 飙高异常的处理

某天，同事告诉我说我在公司负责的一个服务 CPU 占用过高，达到 700% 多（多核 CPU），猜测可能是 gc 比较频繁，让我调一下堆大小，调整过后重新部署，发现 CPU 使用率降至正常水平（6% 左右）。

过了几天想起来这个事，登上服务器看下服务是否正常，发现 CPU 使用率又到了 500% 多，于是就通过一些工具命令排查问题。

初步排查是否是 gc 问题

通过 jstat -gc pid 命令查看 gc 情况，发现进行了 20w 多次 young gc，full gc 只有不到 10 次，于是怀疑是 gc 问题。

再次使用 jstat -gc pid 50 20（每 50ms 打印一次，一共打印 20 次） 命令，发现每秒进行 2 次 young gc，两次 gc 之间都会分配大量的新生代内存（由于当时没有截图，所以不放图了），但是老年代空间几乎没有变化。从打印的结果来看，每次新生代新分配内存都超过 200M，于是确定是某段代码频繁创建对象，导致新生代内存不够，发生 young gc。

由于之前没有过类似的经验，打算根据《深入理解Java虚拟机》这本书里对 jvm 内存问题排查的描述，想着 dump 出内存镜像，再观察新生代的对象，判断具体是哪些对象占用内存过多。但是没有实际进行过这样的操作，而且是要从线上服务 dump heap，所以没有自己动手，等 mentor 有时间的时候一起排查。

动手排查问题

我向 mentor 说了服务的情况和我的想法，但是 mentor 说不一定是 gc 问题，然后 Google 了一下如何排查 CPU 占用过高的问题，发现很多文章都是用同一个方法，就是接下来我要说的方法，找出占用 CPU 过高的线程，再看这些线程在执行哪段代码。

其实这个方法之前查的时候也看到了，但是潜意识里认为是 gc 问题，而且感觉没有直接看内存镜像来得直观，所以也没有动手试。

具体操作步骤如下：
1. jps 命令查看当前运行的 Java 进程，找到异常服务的进程 ID（pid）
2. top -Hp pid 查看该进程所有线程的运行情况，找到占用 CPU 过高的线程 pid
3. printf %x pid 打印出 pid 的 16 进制值（jstack 命令结果中的线程 ID 为 nid，且用 16 进制表示）
4. jstack pid 命令查看线程快照，根据上一步得到的 16 进制值找到具体的线程，就能知道这个进程在执行什么代码了

通过上述步骤，定位到问题是一个工具类的某个方法，对返回结果进行高亮词的标记，开发者使用了 commons-lang 包的 IntRange 类，每找到一个高亮词就会创建一个 IntRange 对象，并且将找到的高亮词进行合并（比如要高亮的词是 Java 和 JavaScript，如果目标字符串有 JavaScript，那么最后就会高亮整个 JavaScript 字符串）、排序（方便下次合并），并且在合并的时候，合并后的结果也创建了一个新的 IntRange 对象，这样就会频繁创建对象。排序使用 JDK 自带的 Collections.sort() 方法，每找到一个词都会合并，也会消耗大量的 CPU 资源。

定位到问题后，对这段代码进行了优化，不使用 IntRange 对象标记找到的高亮词，而是创建一个和目标字符串的大小相同的数组，找到要高亮的词以后把在字符串中的下标映射在数组的下标值设置为 1，这样就不需要合并高亮范围和排序，避免了创建大量对象，整体复杂度大大降低。

排查完问题进行优化以后，CPU 使用率又降到了 6% 左右，连续观察 3 天一切指标正常。

总结

其实这并不是一个 gc 问题导致的 CPU 使用率过高，gc 频繁只是因为创建了太多的对象，并且 gc 线程并没有占用太多的 CPU 资源，根本原因还是代码的时间复杂度太高，CPU 使用率接近 100% 的那几个线程都是在执行高亮代码。