sql执行快并不代表没有问题，排查一起“快”sql引发的数据库高负载

接到一起数据库故障，用户反馈主机cpu频繁告警，操作系统只安装了数据库，查看mysql后没有发现error日志，pt-query-digest分析最近1一个月的slow log，没有找到慢SQL。

数据库主机负载很高，但是找不到慢sql，那么原因出在哪了？

排查过程

• perf top分析cpu高的函数
  查看cpu耗时长的函数，都属于常规的大接口，除了软中断引发关注外，没发现其他异常函数调用。但是从这里可以看出，cpu资源几乎都被mysql服务使用了，且数据库负载较大。
  

• 查看show engine innodb status
  这里再次印证了数据库高负载。如下图，数据库查询非常大，reads/s每秒查询达到了280万行，这已是普通虚拟机的极限了。
  

扩展
inserts/s、updates/s、deletes/s表示数据库TPS。一般好点的机器，TPS可以跑到4000多。

• 查看AHI信息
  粗略计算，数据库AHI命中率约88%，这个值已经非常高了，所以也很好解释上文perf top中AHI相关函数调用高的问题。
  
• 查看fsync()调用执行情况
  读写线程、缓冲池线程、日志线程均无IO受限情况，读、写和fsync()调用执行的数目也合理，这里没有问题。
  

总结

数据库除了负载较高，并无其他异常，所以排查重点应该放在sql查询。

分析原因

一般情况下，如果数据库运行指标正常但负载较高时，我们需要重点分析并发运行线程数和慢sql。

场景1： 数据库存在大量慢SQL
实例中正在运行的慢sql数超过cpu核数时，cpu负载就会很高。
查看show processlist界面很清爽，连接数仅 72个，且看不到运行中的sql，所以排除。

场景2： 数据库并发线程数很高
当数据库sql效率很高，并发很高时，就会有机器负载高而没有慢sql的现象。这里61个并发算是比较高了。但是，这依然无法支撑上文中innodb 280万的超高读的问题。

root@localhost: 14:37: [(none)]> show global status like 'threads_running';
+-----------------+-------+
| Variable_name | Value |
+-----------------+-------+
| Threads_running | 61 |
+-----------------+-------+
1 row in set (0.00 sec)


再次分析慢SQL

使用pt-query-digest解析慢sql，代码段中耗时最长的sql，占用慢sql总耗时的27%，远远高于其他sql。

# Query 2: 0.10 QPS, 0.24x concurrency, ID 0x3607655F960924FCC7CF395219AA3525 at byte 2487347603
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.05
# Time range: 2024-05-09T08:40:02 to 2024-05-21T09:04:53
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 18 103823
# Exec time 22 249294s 2s 22s 2s 3s 350ms 2s
# Lock time 0 16s 58us 19ms 156us 273us 188us 125us
# Rows sent 0 8.20k 0 3 0.08 0 0.40 0
# Rows examine 68 52.10G 521.56k 529.77k 526.19k 509.78k 0 509.78k
# Query size 7 23.37M 236 236 236 236 0 236
# String:
# Hosts 10.xxx (103808/99%), 10.200.5.67 (15/0%)
# Users odmsadmin
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+ #
# Tables
# SHOW TABLE STATUS FROM `odmsdb` LIKE 'oa_mail_record'\G
# SHOW CREATE TABLE `odmsdb`.`oa_mail_record`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT
tm.id,tm.title,tm.body,tm.addressee,tm.operaterType,tm.status,tm.failureCause,
tm.createTime,tm.sendNum,tm.sendTime
FROM oa_mail_record tm
WHERE tm.status ='1' AND tm.sendNum < 6
ORDER BY tm.sendTime
LIMIT 3\G


查看执行计划，首先filtered过滤性很差，其次索引在order by列，这就会导致 where条件在innodb层扫描并返回大量无用的数据，这就很好解释innodb read高的原因了。当耗时短的sql执行频率很高时，也可能造成数据库负载。所以平时也要关注耗时短但执行频率高的sql。

优化方法

新增索引，改变执行计划。分析where字段的选择性后，添加组合组合索引，引导执行计划索引下探，降低扫描行数和数据过滤成本。

alter table oa_mail_record add index idx_status_sendtime(status,sendTime);


优化后的执行计划

另外建议开发归档了部分历史数据，进一步提升了查询效率。优化后，数据库并发线程数降低到10个左右，cpu负载也有明显改善。

写在最后

为了阅读流畅性，很多分析细节并没有展开。比如上文中慢sql所在的表数据量并不大，只有50万行，但是有很多大字段，比如存储邮件正文等，这就导致扫描成本较高。

root@localhost: 15:45: [odmsdb]> desc oa_mail_record;
+--------------+--------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+--------------+--------------+------+-----+---------+-------+
| id | char(32) | NO | PRI | NULL | |
| title | varchar(255) | YES | | NULL | |
| body | longtext | YES | | NULL | |
| addressee | longtext | YES | | NULL | |
| operaterType | varchar(32) | YES | | NULL | |
| status | char(1) | YES | MUL | NULL | |
| failureCause | longtext | YES | | NULL | |
| createTime | datetime | YES | | NULL | |
| sendNum | int(11) | YES | | NULL | |
| sendTime | datetime | YES | MUL | NULL | |
+--------------+--------------+------+-----+---------+-------+
10 rows in set (0.00 sec)