你要偷偷学会排查线上 CPU 飙高的问题，然后惊艳所有人 - 今日头条

本文由简悦 SimpRead 转码，原文地址 www.toutiao.com

前段时间我们新上了一个新的应用，因为流量一直不大，集群 QPS 大概只有 5 左右，写接口的 rt 在 30ms 左右。

前段时间我们新上了一个新的应用，因为流量一直不大，集群 QPS 大概只有 5 左右，写接口的 rt 在 30ms 左右。

因为最近接入了新的业务，业务方给出的数据是日常 QPS 可以达到 2000，大促峰值 QPS 可能会达到 1 万。

所以，为了评估水位，我们进行了一次压测。压测过程中发现，当单机 QPS 达到 200 左右时，接口的 rt 没有明显变化，但是 CPU 利用率急剧升高，直到被打满。

压测停止后，CPU 利用率立刻降了下来。

于是开始排查是什么导致了 CPU 的飙高。

问题排查与解决

在压测期间，登录到机器，开始排查问题。

本案例的排查过程使用的阿里开源的 Arthas 工具进行的，不使用 Arthas，使用 JDK 自带的命令也是可以。

在开始排查之前，可以先看一下 CPU 的使用情况，最简单的就是使用 top 命令直接查看：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13


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，接下来开始排查具体是哪个线程，哪段代码比较耗 CPU。

首先，下载 Arthas 命令：

1

curl -L http://start.alibaba-inc.com/install.sh | sh

启动

1

./as.sh

使用 Arthas 命令 "thread -n 3 -i 1000" 查看当前 "最忙"（耗 CPU）的三个线程：

通过上面的堆栈信息，可以看出，占用 CPU 资源的线程主要是卡在 JDBC 底层的 TCP 套接字读取上。连续执行了很多次，发现很多线程都是卡在这个地方。

通过分析调用链，发现这个地方是我代码中有数据库的 insert，并且使用 TDDL（阿里内部的分布式数据库中间件）来创建 sequence，在 sequence 的创建过程中需要和数据库有交互。

但是，基于对 TDDL 的了解，TDDL 每次从数据库中查询 sequence 序列的时候，默认会取出 1000 条，缓存在本地，只有用完之后才会再从数据库获取下一个 1000 条序列。

按理说我们的压测 QPS 只有 300 左右，不应该这么频繁的何数据库交互才对。但是，经过多次使用 Arthas 的查看，发现大部分 CPU 都耗尽在这里。

于是开始排查代码问题。最终发现了一个很傻的问题，那就是我们的 sequence 创建和使用有问题：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33


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 语句都重新 build 了一个新的 sequence，这就导致本地缓存就被丢掉了，所以每次都会去数据库中重新拉取 1000 条，但是只是用了一条，下一次就又重新取了 1000 条，周而复始。

于是，调整了代码，把 Sequence 实例的生成改为在应用启动时初始化一次。这样后面在获取 sequence 的时候，不会每次都和数据库交互，而是先查本地缓存，本地缓存的耗尽了才会再和数据库交互，获取新的 sequence。

1
2
3
4
5
6


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。

所以，通过在预发布中关闭 DP 对 TDDL 的采集，即可解决该问题。

总结与思考

本文总结了一次线上 CPU 飙高的问题排查过程，其实问题都不难，并且还挺傻的，但是这个排查过程是值得大家学习的。

其实在之前自己排查过很多次 CPU 飙高的问题，这次也是按照老方法进行排查，但是刚开始并没有发现太大的问题，只是以为是流量升高导致数据库操作变多的正常现象。

期间又多方查证（通过 Arthas 查看 sequence 的获取内容、通过数据库查看最近插入的数据的主键 ID 等）才发现是 TDDL 的 Sequence 的初始化机制有问题。

在解决了这个问题之后，以为彻底解决问题，结果又遇到了 DP 采集 TDDL 日志导致 CPU 飙高，最终再次解决后有了明显提升。

所以，事出反常必有妖，排查问题就是一个抽丝剥茧的过程。

：Hollis（ID：hollischuang），一个对 Coding 有着独特追求的人，现任阿里巴巴技术专家，个人技术博主，技术文章全网阅读量数千万，《程序员的三门课》联合作者。关于作者**