【是否原创】是
【首发渠道】TiDB 社区
【正文】

1.概述

2022 年春节放假前巡检线上 TiDB 集群时，发现一套集群的 TiDB Server 服务器 CPU 使用率较高，达到 4000% 到 5000% 之间，平时这套集群的 CPU 使用率在 1500% 以下，于是开始分析排查集群是否正常，避免留下隐患。

2.问题现象

TiDB 集群版本是 4.0.9，TiDB Server 服务器 CPU 核数 112，单机部署 3 个 TiDB Server 实例，三台服务器共 9 个 TiDB Server，使用 LVS 做负载均衡。下面是集群的一些基础监控信息。

集群 QPS

集群 Duration

TiDB Server CPU 使用率

TiDB Server 内存使用情况

TiKV 服务器的 CPU、内存、IO 等指标均正常，这里不再列出，以上只截图了一些 TiDB Server 相关的部分监控，从以上信息可以看到，TiDB Server 主要的问题在于 CPU 使用率较高，而集群的 QPS 并不高，内存和 Duration 看着也良好，以上是基本现象。

3.问题分析

分析慢日志
排除并发高的因素，一般情况下，TiDB Server CPU 高很可能是大查询或者聚合查询等比较耗费计算资源的 SQL 导致的，我们先分析一下慢日志，看是否有异常 SQL 。通过分析慢日志，未发现明显异常，慢日志里大部分是 delete 的 sql，类似如下：

DELETE FROM UserBehaviorHistory_hash WHERE id BETWEEN 68724071977 AND 68724072177 AND create_time <= DATE_SUB(CURDATE(), INTERVAL 25 DAY);

SQL 比较简单，并发也不高，理论上不会消耗太多 CPU 资源。

分析监控
通过对比几天前的监控发现，delete 的 qps 增加 2.5 倍左右，之前是 500 左右，现在是 1300 左右，但是 set 的量却增加了 30 倍(128–>3930)，set 的数量增加的非常多，这里引起了我们的注意。
分析系统表
为了进一步确认 set 执行情况，我们借住 TiDB 系统表辅助分析。

TiDB 系统表 CLUSTER_STATEMENTS_SUMMARY 是用来监控和统计 SQL，我们按照执行次数排序，看下 SQL 执行情况信息。

dba@xx.xx.xx.xx:4000 : information_schema > select INSTANCE,STMT_TYPE,SCHEMA_NAME,DIGEST_TEXT,EXEC_COUNT,SUMMARY_BEGIN_TIME,SUMMARY_END_TIME from CLUSTER_STATEMENTS_SUMMARY order by EXEC_COUNT desc limit 5;
+--------------------+-----------+---------------+--------------------+------------+---------------------+---------------------+
| INSTANCE           | STMT_TYPE | SCHEMA_NAME   | DIGEST_TEXT        | EXEC_COUNT | SUMMARY_BEGIN_TIME  | SUMMARY_END_TIME    |
+--------------------+-----------+---------------+--------------------+------------+---------------------+---------------------+
| xx.xx.xx.xx:10082 | Set       | personalspace | set autocommit = ? |     754706 | 2022-01-25 21:30:00 | 2022-01-25 22:00:00 |
| xx.xx.xx.xx:10080 | Set       | personalspace | set autocommit = ? |     650292 | 2022-01-25 21:30:00 | 2022-01-25 22:00:00 |
| xx.xx.xx.xx:10082 | Set       | personalspace | set autocommit = ? |     592365 | 2022-01-25 21:30:00 | 2022-01-25 22:00:00 |
| xx.xx.xx.xx:10081 | Set       | personalspace | set autocommit = ? |     548287 | 2022-01-25 21:30:00 | 2022-01-25 22:00:00 |
| xx.xx.xx.xx:10082 | Set       | personalspace | set autocommit = ? |     527409 | 2022-01-25 21:30:00 | 2022-01-25 22:00:00 |
+--------------------+-----------+---------------+--------------------+------------+---------------------+---------------------+
5 rows in set (0.02 sec)

TOP 5 的 SQL 全部是 set autocommit = 1，不完全统计，仅前五名加在一起在半个小时内执行了 300 多万次，量确实有点大。

分析 general log
为什么会执行这么多次 set autocommit，为了一探究竟，打开一个 TiDB Server 实例的 general log，看下到底在干什么。

下面是单个实例上执行次数不完全统计

[root@p-xx-xx-xx log]# grep '25 21:29:' tidb.log | grep -i 'SET autocommit' | wc -l
17713
[root@p-xx-xx-xx log]# grep '25 21:30:' tidb.log | grep -i 'SET autocommit' | wc -l
17509
[root@p-xx-xx-xx log]# grep '25 21:31:' tidb.log | grep -i 'SET autocommit' | wc -l
17866

下面是过滤固定连接 conn=432129986 后的信息

[root@p-xx-xx-xx log]# grep 'conn=432129986' tidb.log 
[2022/01/25 21:32:25.915 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="  DELETE FROM UserBehaviorHistory_hash  WHERE id BETWEE
N 69825310177 AND 69825310377 AND create_time <= DATE_SUB(CURDATE(), INTERVAL 25 DAY)          "]
[2022/01/25 21:32:25.929 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="select 1 as heartbeat"]
[2022/01/25 21:32:25.929 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="set session transaction read write"]
[2022/01/25 21:32:25.929 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="SET autocommit=1"]
[2022/01/25 21:32:25.930 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="SET autocommit=1"]
[2022/01/25 21:32:25.940 +08:00] [INFO] [session.go:2287] [GENERAL_LOG] [conn=432129986] [user=personalspace_wr@xx.xx.xx.xx] [schemaVersion=2735] [txnStartTS
=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=personalspace] [txn_mode=OPTIMISTIC] [sql="  DELETE FROM UserBehaviorHistory_hash  WHERE id BETWEE
N 69825310377 AND 69825310577 AND create_time <= DATE_SUB(CURDATE(), INTERVAL 25 DAY)          "]

从以上信息得出两个结论：
（1）每一个 delete 语句后都跟着一条 select 1 as heartbeat、一条 set session transaction read write 和两条 SET autocommit=1。

（2）这种多余的 select 语句和 set 语句量非常大。

猜测 TiDB Server CPU 高的原因和这有关系，为了证明猜测，接下来对这种语句进行简单压测。

4.压测

为了验证上一步提出的猜测是否正确，本节对这些语句简单压测。压测工具使用的是mydbtest(mydbtest_linux64.bin，由楼方鑫编写)，该压测软件区别于 sysbench，tpcc 等常见压测工具软件，免安装，上手快，而且可以针对业务 sql 做定制化压测。

并发 4 线程压测，压测过程省略，压测 CPU 截图如下
image%20(5)

说明

压测 SQL	压测时间段
SET autocommit=1	9:55-9:59
select 1 as heartbeat	10:00-10:05
set session transaction read write	10:05-10:11
上面 3 个 sql 一块跑	10:11-10:16

从以上压测结果可以得出结论：这些语句对 QPS 和性能及 CPU 等有影响。本节只是做一个简单压测用于定性分析，不做定量测试。

5.解决方案

业务开发语言是 scale，访问 TiDB 使用的是 ScalikeJDBC。通过之前的分析，我们知道导致 CPU 高的原因是每一个 DML 语句都跟着好几个多余的语句(SET autocommit=1 等)，那么如何减少这些多余的语句呢？官网最佳实践给出了答案（原文如下）：

通过监控可能会发现，虽然业务只向集群进行 insert 操作，却看到有很多多余的 select 语句。通常这是因为 JDBC 发送了一些查询设置类的 SQL 语句（例如 select @@session.transaction_read_only）。这些 SQL 对 TiDB 无用，推荐配置 useConfigs=maxPerformance 来避免额外开销。

useConfigs = maxPerformance 会包含一组配置：

cacheServerConfiguration = true

useLocalSessionState = true

elideSetAutoCommits = true

alwaysSendSetIsolation = false

enableQueryTimeouts = false

一个建议的 url 配置如下：

spring.datasource.url=JDBC:mysql://{TiDBIP}:{TiDBPort}/{DBName}?characterEncoding=utf8&useSSL=false&useServerPrepStmts=true&prepStmtCacheSqlLimit=10000000000&useConfigs=maxPerformance&rewriteBatchedStatements=true&defaultfetchsize=-214783648&allowMultiQueries=true&socketTimeout=3000&connectTimeout=1200

官网最佳实践
https://docs.pingcap.com/zh/tidb/v4.0/java-app-best-practices

6.优化效果

JDBC 中增加 useConfigs=maxPerformance 配置后，分析 general log ，类似 SELECT @@session.transaction_read_only 和 SET autocommit=1 的语句消失了。general log 简化后的片段如下：

优化前

select 1 as heartbeat  # druid 连接池心跳检测语句
set session transaction read write
SET autocommit=1
SET autocommit=1
DELETE FROM UserBehaviorHistory_hash  WHERE id BETWEEN 69825314777 AND 69825314977 AND create_time <= DATE_SUB(CURDATE(), INTERVAL 25 DAY)

优化后

select 1 as heartbeat  # druid 连接池心跳检测语句
DELETE FROM UserBehaviorHistory_hash  WHERE id BETWEEN 69825314777 AND 69825314977 AND create_time <= DATE_SUB(CURDATE(), INTERVAL 25 DAY)

伴随着多余语句的消失，TiDB Server 的 CPU 使用率下降显著。

7.总结

这些多余语句量少的时候，一般不会有什么问题，也不会引起我们的注意，但是量很大时，就会消耗大量 TiDB Server 的 CPU 资源，因为需要 CPU 资源去解析这些多余语句。本文通过一个简单生产优化案例说明了这类问题的现象，解决办法，优化效果。

附加

曾经遇到过 @Transactional 使用不当导致的数据库(MySQL)性能问题：

2020 年 7 月 27 号压测 VR 业务时，数据库的 QPS 在 2 万左右，CPU 在 20% 以下，但是在 8 月 2 号压测时，数据库的 QPS 在 2 千左右时，CPU 却高达 80% 。经过抓包分析，业务在 04:34:58 至 04:35:14 之间仅仅 16 秒的时间执行了 59 万次 SET autocommit=0 和 29 万次 Commit，从而导致了性能问题，和业务方一起沟通优化后问题解决。

原因是：@Transactional 滥用导致；解决办法是：将代码中没有用到事务和不必用事务的地方去掉相应 @Transactional 即可。

下面是［阿里巴巴Java开发手册］里的 @Transactional 相关规范，仅供参考：

【参考】@Transactional 事务不要滥用。事务会影响数据库的 QPS，另外使用事务的地方需要考虑各方面的回滚方案，包括缓存回滚、搜索引擎回滚、消息补偿、统计修正等。

大量 SET autocommit 导致的 TiDB Server CPU 高案例