上篇提到了什么是 CPU 以及如何计算的。接下来主要说说实际工作中遇到 CPU 飙高如何去排查呢？
往期回顾：
问题发现
前段时间我们新上线了一个应用，由于流量一直不大，集群的每秒查询率（QPS）大约只有 5。接口的响应时间大约在 30 毫秒左右。
最近我们接入了新的业务，业务方提供的数据显示，日常的 QPS 预计可以达到 2000，而在大促期间峰值 QPS 可能会达到 1 万。
为了评估系统的性能水平，我们进行了一次压力测试。测试在预发布环境进行。在压力测试过程中，我们观察到当单台服务器的 QPS 达到约 200 时，接口的响应时间没有明显变化，但是 CPU 利用率迅速上升，直到达到极限。
压力测试结束后，CPU 利用率立即下降。
随后我们开始排查是什么原因导致了 CPU 的突然飙升。
排查与解决
在压力测试期间，登录到机器后，我们开始排查问题。
本案例的排查过程使用了阿里开源的 Arthas 工具。如果没有 Arthas，也可以使用 JDK 自带的命令进行排查。
在开始具体排查之前，可以先查看 CPU 的使用情况。最简单的方法是使用top命令直接查看：
top - 10:32:38 up 11 days, 17:56, 0 users, load average: 0.84, 0.33, 0.18
Tasks: 23 total, 1 running, 21 sleeping, 0 stopped, 1 zombie
%Cpu(s): 95.5 us, 2.2 sy, 0.0 ni, 76.3 id, 0.0 wa, 0.0 hi, 0.0 si, 6.1 st
KiB Mem : 8388608 total, 4378768 free, 3605932 used, 403908 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 4378768 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3480 admin 20 0 7565624 2.9g 8976 S 241.2 35.8 649:07.23 java
1502 root 20 0 401768 40228 9084 S 1.0 0.5 39:21.65 ilogtail
181964 root 20 0 3756408 104392 8464 S 0.7 1.2 0:39.38 java
496 root 20 0 2344224 14108 4396 S 0.3 0.2 52:22.25 staragentd
1400 admin 20 0 2176952 229156 5940 S 0.3 2.7 31:13.13 java
235514 root 39 19 2204632 15704 6844 S 0.3 0.2 55:34.43 argusagent
236226 root 20 0 55836 9304 6888 S 0.3 0.1 12:01.91 systemd-journ
可以清楚的看到，进程 ID 为 3480 的 Java 进程占用了较高的 CPU，可以初步推断是应用代码执行过程中消耗了大量的 CPU 资源。接下来，我们需要进一步排查是哪个线程、哪段代码导致了这种情况。
首先，我们需要下载 Arthas 工具：
curl -L https://arthas.aliyun.com/install.sh | sh
启动：
./as.sh
使用 Arthas 命令 "thread -n 3 -i 1000"查看当前"最忙"（耗 CPU）的三个线程：
通过上述堆栈信息可以看出，占用 CPU 资源的线程主要是在 JDBC 底层的 TCP 套接字读取上阻塞。经过连续执行多次分析，发现很多线程都在这个地方卡住。
进一步分析调用链后发现，这个问题源自于我代码中的数据库 insert 操作，其中使用了 TDDL 来创建 sequence。在 sequence 的创建过程中，需要与数据库进行交互。
根据对 TDDL 的了解，它每次从数据库查询 sequence 序列时，默认会获取 1000 条，并在本地进行缓存，直到使用完这 1000 条序列之后才会再次从数据库获取下一个 1000 条序列。
考虑到我们的压测 QPS 仅约为 300 左右，不应该导致如此频繁的数据库交互。然而，通过多次使用 Arthas 进行查看，发现大部分的 CPU 资源都耗费在这里。
因此，我们开始排查代码问题。最终，发现了一个非常简单的问题，即我们的 sequence 创建和使用存在着明显的缺陷：
public Long insert(T dataObject) {
if (dataObject.getId() == null) {
Long id = next();
dataObject.setId(id);
}
if (sqlSession.insert(getNamespace() + ".insert", dataObject) > 0) {
return dataObject.getId();
} else {
return null;
}
}
public Sequence sequence() {
return SequenceBuilder.create()
.name(getTableName())
.sequenceDao(sequenceDao)
.build();
}
/**
* 获取下一个主键ID
*
* @return
*/
protected Long next() {
try {
return sequence().nextValue();
} catch (SequenceException e) {
throw new RuntimeException(e);
}
}
因此，我们每次执行 insert 语句时都重新构建了一个新的 sequence 对象，这导致本地缓存被清空。因此，每次都需要从数据库重新获取 1000 条 sequence，但实际上只使用了一条，下次又会重复这个过程。
为了解决这个问题，我们调整了代码，在应用启动时初始化了一个 Sequence 实例。这样，在后续获取 sequence 时，不会每次都与数据库交互。而是首先检查本地缓存，只有在本地缓存用尽时才会再次与数据库交互，获取新的 sequence。
public abstract class BaseMybatisDAO implements InitializingBean {
@Override
public void afterPropertiesSet() throws Exception {
sequence = SequenceBuilder.create().name(getTableName()).sequenceDao(sequenceDao).build();
}
}
通过实现 InitializingBean 接口，并重写其中的 afterPropertiesSet()方法，在该方法中进行 Sequence 的初始化。
完成以上代码修改后，提交并进行验证。根据监控数据显示，优化后数据库的读取响应时间（RT）明显下降。
sequence 的写操作 QPS 也有明显下降：
于是我们开始了新的一轮压测，但是发现 CPU 的使用率仍然很高，压测的 QPS 还是无法达到预期。因此，我们决定重新使用 Arthas 工具查看线程的情况。
发现了一个 CPU 消耗较高的线程堆栈，主要是因为我们在使用一个联调工具时，该工具预发布状态下默认开启了 TDDL 的日志采集（尽管官方文档中描述预发布状态下默认不会开启 TDDL 采集，但实际上确实会进行采集）。
在该工具打印日志时，会进行数据脱敏操作，脱敏框架使用了 Google 的 re2j 进行正则表达式匹配。
由于我的操作涉及到大量的 TDDL 操作，而默认情况下会采集大量 TDDL 日志并进行脱敏处理，这导致了较高的 CPU 消耗。
因此，通过在预发布环境中关闭对 TDDL 的日志采集，可以有效解决这个问题。
总结
这篇总结回顾了一次线上 CPU 飙高问题的排查过程，虽然问题最终解决起来并不复杂，但排查过程中却有其独特的教育意义。
之前经验丰富的我按照惯例进行了排查，初始阶段并未发现明显问题，错误地将数据库操作增加归因于流量上升所致的正常情况。
通过多方查证（例如使用 arthas 查看序列获取情况，以及通过数据库查询最新插入数据的主键 ID 等方法），最终确认问题出在 TDDL 的序列初始化机制上。
解决了这个问题后，本以为问题彻底解决，却又遭遇到 DP 采集 TDDL 日志导致 CPU 飙高的情况，最终再次解决问题后系统性能有了显著提升。
因此，这个经历再次验证了“事出反常必有妖”，排查问题确实需要有耐心和系统性。
如有问题，欢迎微信搜索【码上遇见你】。
好了，本章节到此告一段落。希望对你有所帮助，祝学习顺利。
