一次线上慢SQL问题的定位分析
一. 背景
项目组内为了解耦部分业务流程，通过一个轻量的内部队列，将非主要流程进行异步化。
具体方式是，在db中创建了一个消息队列表，表结构如下所示
CREATE TABLE `t_asyncqueue` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`foreignId` bigint(20) NOT NULL DEFAULT '0' COMMENT '关联外键ID',
`serviceId` int(11) NOT NULL DEFAULT '0' COMMENT '服务ID',
`context` text COMMENT 'json',
`executeTime` timestamp NULL DEFAULT NULL COMMENT '执行时间',
`status` int(11) DEFAULT '0' COMMENT '未处理0, 处理中1, 已处理2, 处理失败3',
`recordStatus` tinyint(4) DEFAULT '0' COMMENT '状态 0默认 -1删除',
`createTime` timestamp NULL DEFAULT NULL COMMENT '创建日期',
`updateTime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
PRIMARY KEY (`id`),
KEY `idx_serviceId_status_executeTime` (`serviceId`,`status`,`executeTime`),
KEY `idx_foreignId_serviceId` (`foreignId`,`serviceId`),
KEY `idx_status_serviceId` (`status`,`serviceId`),
KEY `idx_updateTime` (`updateTime`),
KEY `idx_createTime` (`createTime`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
并根据serviceId做配置，配置项大致如下所示
[10_xxxx]
serviceId=10
callback=http://test.org/callback/api_test_callback
concurrency=4
send_timeout=2
每个serviceId有一个自己的线程池，线程的数量就是配置中并发数量。
使用下面示例sql进行任务拉取后，分配给各个线程进行处理回调，成功或失败都会更新db中的status字段值
SELECT
*
FROM
t_asyncqueue
WHERE
serviceId = 10
and status = 0
and executeTime < {当前时间戳}
ORDER BY
id DESC
LIMIT
100
另外一个单独的后台线程会定时清理status=2的数据记录。
所以正常情况下，数据表中数据量在2w ~ 5w左右。
二. 具体场景
1. 问题产生
8月5日时，有同学刷数据，向表中投放了大量任务，量级在30w+。
随后监控发现线上产生了大量的慢sql(如下图所示)，通过查询慢SQL日志发现都是来自这个消息队列表。
负责该功能模块的同学，进行了问题的查找后，给出了是由于另外一个同学在查询后台中执行了一个连表查询SQL(其他两个表)，导致了消息队列表慢SQL的结论。
对于给出的这个解释，着实有点违背了常识，让人哭笑不得。
从内存占用上分析
连表查询时依赖读取数据线程的join buffer，这个buffer的大小是由join_buffer_size设定的，默认值是 256k。
流程如下：
- 从驱动表中取数据，直到join buffer写满
- 从被驱动表取数据，判断是否满足join条件，若满足则返回给上层
- 清空join buffer
- 不断重复1 2 3步骤，直到驱动表数据读取完成
整个过程占用的内存是不会超过join_buffer_size的。
而发送时，mysql采用的是边读边发的方式，每个连接有自己的buffer，默认是16k
发送流程如下：
- 从存储引擎中读取数据，存入到buffer中
- buffer写满，数据写入socket buffer进行发送
- 发送成功，清空buffer
- 不断重复1 2 3步骤，直到数据发送完成
所以不存在占用内存过高的问题。
不然做备份的时候，从库内存岂不是直接被打爆？
从CPU占用上分析
CPU是公共资源，如果是由于两表联合查询占用了过多的CPU，不可能只有这一个表产生慢SQL。
总结这个说法是说不通的
罗列可能情况
在进行具体分析前，脑海中大致先回忆一下慢SQL产生的原因可能有哪些
- 扫描了过多的行（未使用到索引/使用错误索引/本身数据量大）
- 使用了文件排序
- 锁竞争等待
- redo log满了或内存页不足 flush脏页
- rr模式下，存在长事务导致undo log过长，为了保持一致性读查找的时间过长
查看执行计划
mysql> explain select * FROM t_asyncqueue WHERE foreignId = 2022070500022525 and serviceId = 100 and status = 0 for update;
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
| 1 | SIMPLE | t_asyncqueue | ref | idx_status_serviceId,idx_foreignid_serviceId,idx_serviceId_status_executeTime | idx_foreignid_serviceId | 12 | const,const | 1 | Using where |
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
1 row in set (0.00 sec)
可以得知
- SELECT操作使用了索引，且扫描的行数很少，故排除第一种情况
- 虽然使用了order by 但是limit的数据量很少 故慢排除了第二种情况
- 再通过DBA查询实例运行情况，也排除掉了4 5两个情况
那么就仅剩锁竞争的这个情况了，需要根据日志来进行实际情况的排查。
2. 分析日志
通过查看日志，发现在产生慢SQL的时间段内，日志中的确爆出大量死锁异常。
由于没有触发报警阈值，没有收到报警，第一时间想到的是机器负载问题 此处线上应该调低报警阈值，便于及时发现问题
合理怀疑因「锁竞争」问题激烈，而导致等待时间过长，产生大量慢SQL。
通过pt工具导出峰值时间内慢SQL的日志汇总信息，如下所示
# 3s user time, 70ms system time, 23.30M rss, 176.65M vsz
# Current date: Fri Aug 7 11:44:51 2020
# Hostname: tjtx-124-225.58os.org
# Files: /opt/dbtools/mysql/logs/20200807/3232_detailslow_20200807114415
# Overall: 13.76k total, 16 unique, 11.47 QPS, 5.35x concurrency _________
# Time range: 2020-08-05 13:50:00 to 14:09:59
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 6410s 100ms 16s 466ms 2s 893ms 155ms
# Lock time 481s 16us 11s 35ms 93us 340ms 47us
# Rows sent 54.87k 0 128 4.08 11.95 18.86 0
# Rows examine 224.35M 0 838.61k 16.70k 34.95 108.14k 0
# Query size 1.82M 57 11.16k 138.57 158.58 118.74 143.84
下面对日志进行解读如下： Overall: 总执行13.76k个语句 16 unique：去重后共16个语句 Exec time：总执行时间6410s Lock time：锁占用时间481s
下面来看一下慢SQL语句排行
# Profile
# Rank Query ID Response time Calls R/Call V/M I
# ==== ============================== =============== ===== ====== ===== =
# 1 0x685EACFE7FE9030BE39F0228D... 3506.4944 54.7% 4573 0.7668 2.40 UPDATE t_asyncqueue
# 2 0xF548CD1DE91F6103EADE925AA... 1862.3299 29.1% 3068 0.6070 0.58 SELECT t_asyncqueue
# 3 0x26C0EE565DDCB20FFC7BCB25F... 625.4511 9.8% 3834 0.1631 0.02 SELECT t_asyncqueue
# 4 0x6600E8E220EB98A764958F56C... 335.5374 5.2% 2102 0.1596 0.02 SELECT t_asyncqueue
# MISC 0xMISC 80.5836 1.3% 180 0.4477 0.0 <12 ITEMS>
排行第一名的是一个update语句，也就是更新任务执行状态的语句。
UPDATE
t_asyncqueue
SET
status = 2,
updateTime = NOW()
where
serviceId = 10
AND status = 0
AND recordStatus = 0
AND updateTime < date_add(now(), interval -1 minute)
查找该语句的日志详情，锁占用的时间比例很大，具体如下
# Query 1: 3.81 QPS, 2.92x concurrency, ID 0x685EACFE7FE9030BE39F0228DE761611 at byte 2326531
# This item is included in the report because it matches --limit.
# Scores: V/M = 2.40
# Time range: 2020-08-05 13:50:00 to 14:09:59
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 33 4573
# Exec time 54 3506s 100ms 14s 767ms 4s 1s 189ms
# Lock time 95 458s 28us 11s 100ms 152us 558ms 54us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 97 219.16M 0 838.47k 49.07k 650.62k 181.63k 0
# Query size 39 727.93k 163 163 163 163 0 163
# String:
# Databases -
# Hosts -
# Users -
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s ################
# 10s+ #
执行show engine innodb status，查看LATESTDETECTED DEADLOCK最后一次死锁信息，如下图所示。
第一个事务
UPDATE
t_asyncqueue
SET
status = 2,
updateTime = NOW()
WHERE
foreignId = 202008100012512
and serviceId = 25
and status = 0
等待锁信息
- RECORD LOCKS ：说明是在等一个记录锁
- id 3003 page no 14857 ：是记录所在位置
- index `idx_status_serviceId`：要锁的是二级索引
- lock_mode X wating ：说明要加上一个写锁 持有的锁没有说，可以通过第二个事务来推断出，继续向下看
第二个事务
UPDATE
t_asyncqueue
SET
status = 2,
updateTime = NOW()
WHERE
foreignId = 202008100012528
and serviceId = 25
and status = 0
等待锁信息
- RECORD LOCKS ：说明是在等一个记录锁
- id 3003 page no 12544 ：是记录所在位置
- index `PRIMARY`：是要锁主键索引
- lock_mode X wating ：说明要等待加上一个写锁
3. 分析原因
可以看出「事务1」持有了记录A的主键行锁，而「事务2」持有了二级索引idx_status_serviceId记录A的行锁，等待给记录A的主键索引加X锁。
在分析锁前，首先来确定下，数据库的隔离级别是什么
mysql> show variables like '%tx_isolation%';
+---------------+-----------------+
| Variable_name | Value |
+---------------+-----------------+
| tx_isolation | REPEATABLE-READ |
+---------------+-----------------+
1 row in set (0.00 sec)
可以看到是可重复读（RR），那么脑海里先回忆一下在RR模式下的加锁过程
- 加锁的默认单位是next-key lock，左开右闭，等值查询时唯一索引时退化为行锁。
- 语句按顺序扫到的记录，对它的二级索引及对应主键索引加X锁，并在commit之后释放。
这里就有疑问了，如果是走同一个索引，两个SQL就会以同样的顺序进行扫二级索引->加锁->找主键索引->加锁。
那么产生的情况就会是:前一个SQL加锁成功，后一个SQL block住等待释放锁。而不可能会是，两个事务互相持有对方的锁的情况。
测试环境下，使用select for update语句+标注force index进行验证后，确实是会block住
那么什么情况下，两个事务都锁同一个二级索引和主键索引，没有加order by但是锁的顺序却不一致呢？
先回顾了一下表上的索引建立情况，这里猜测可能是命中了index merge优化的情况。
即每个sql都同时走了多个索引进行数据查询加锁，流程如下
- 事务1通过
其他索引在主键上加了X锁，想再通过idx_status_serviceId索引扫描数据加锁 - 事务2先将
idx_status_serviceId索引加锁，在去对应主键索引上加锁 - 事务1持有主键行锁，事务2持有二级索引行锁，互相等待对方释放，产生死锁
下面来验证一下想法
首先查看index_merge是否开启
mysql> SELECT @@optimizer_switch\G
*************************** 1. row ***************************
@@optimizer_switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,engine_condition_pushdown=on
1 row in set (0.01 sec)
这里再回顾一下sql的执行计划
mysql> explain select * FROM t_asyncqueue WHERE foreignId = 2022070500022525 and serviceId = 100 and status = 0 for update;
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
| 1 | SIMPLE | t_asyncqueue | ref | idx_status_serviceId,idx_foreignid_serviceId,idx_serviceId_status_executeTime | idx_foreignid_serviceId | 12 | const,const | 1 | Using where |
+----+-------------+------------------------+------+-------------------------------------------------------------------------------+-------------------------+---------+-------------+------+-------------+
1 row in set (0.00 sec)
Extra列没有显示用到index merge？
这就很奇怪了，思考索引使用流程，分析后得出以下猜测：
执行计划会根据页采样的「数据多样性」来确定哪种执行方式成本更低。
当基础数据够多且status为0的数据和符合foreignId的数据都很少时，就会采用index merge的方式并行查找，再取数据交集。
而由于表中的数据一直在动态的新增/变更/删除，索引的采样数据也会一直在变化，导致执行计划也会不同。
所以事发后查看的sql执行计划不能确定就是当时的执行计划，也就能解释为什么执行计划中没有显示了。
4. 解决问题
已知了问题出现的原因后，有几种方式可以解决该现象
- sql中使用force index，强制指定某个索引
- 关闭index merge，需要重启实例后生效
- 删除index merge时使用的多个索引中的不必要的索引
这里为了快速验证，所以选择了第一种方式，直接修改了sql，在观察一段时间后没有再出现慢sql和死锁情况。
后续根据SQL使用情况，酌情修改优化索引。
三. 总结
这次事故产生了大量的慢SQL，在排除了多种情况后，通过日志确定是由于锁竞争产生了死锁，导致后续sql的等待时间过多而产生。
虽然导致死锁的原因是由index merge优化策略产生，但是究其根本是因为索引创建的不合理，并且这种情况很隐晦，数据量上涨且索引的数据样本产生倾斜后，才爆发出来。
所以，在操作数据和建立索引时，应当做到以下几点
- 同组资源按照相同的顺序访问，避免产生死锁的概率
- 尽量不要为sql使用的每字段分别建立单独索引，结合使用场景和最左前缀匹配原则正确的建立联合索引（多列索引）
- 有必要时可以使用force index（也许不太优雅），毕竟MySQL的优化器也有不靠谱的时候
- 脑海里要有sql执行的整个流程，在操作数据表和排查问题的时候，思考是否有分支会存在问题
转载自:https://juejin.cn/post/7117986579938803725