1
0
2
0
专栏/.../

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

 mydb  发表于  2022-02-15

【是否原创】是
【首发渠道】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
image

集群 Duration

image%20(1)

TiDB Server CPU 使用率

image%20(2)

TiDB Server 内存使用情况

image%20(3)

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 的数量增加的非常多,这里引起了我们的注意。
    image%20(4)
  • 分析系统表
    为了进一步确认 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,另外使用事务的地方需要考虑各方面的回滚方案,包括缓存回滚、搜索引擎回滚、消息补偿、统计修正等。

1
0
2
0

版权声明:本文为 TiDB 社区用户原创文章,遵循 CC BY-NC-SA 4.0 版权协议,转载请附上原文出处链接和本声明。

评论
暂无评论