「性能指标」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 工具：

1 2	curl -L https://arthas.aliyun.com/install.sh \| sh

启动：

1
2

./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 也有明显下降：