一次线上慢SQL问题的定位分析

·  阅读 1411

一. 背景

项目组内为了解耦部分业务流程,通过一个轻量的内部队列,将非主要流程进行异步化。

具体方式是,在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。

流程如下:

  1. 从驱动表中取数据,直到join buffer写满
  2. 从被驱动表取数据,判断是否满足join条件,若满足则返回给上层
  3. 清空join buffer
  4. 不断重复1 2 3步骤,直到驱动表数据读取完成

整个过程占用的内存是不会超过join_buffer_size的。

而发送时,mysql采用的是边读边发的方式,每个连接有自己的buffer,默认是16k

发送流程如下:

  1. 从存储引擎中读取数据,存入到buffer中
  2. buffer写满,数据写入socket buffer进行发送
  3. 发送成功,清空buffer
  4. 不断重复1 2 3步骤,直到数据发送完成

所以不存在占用内存过高的问题。

不然做备份的时候,从库内存岂不是直接被打爆?

从CPU占用上分析

CPU是公共资源,如果是由于两表联合查询占用了过多的CPU,不可能只有这一个表产生慢SQL。

总结这个说法是说不通的

罗列可能情况

在进行具体分析前,脑海中大致先回忆一下慢SQL产生的原因可能有哪些

  1. 扫描了过多的行(未使用到索引/使用错误索引/本身数据量大)
  2. 使用了文件排序
  3. 锁竞争等待
  4. redo log满了或内存页不足 flush脏页
  5. 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最后一次死锁信息,如下图所示。

image.png

第一个事务

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. 事务1通过其他索引在主键上加了X锁,想再通过idx_status_serviceId索引扫描数据加锁
  2. 事务2先将idx_status_serviceId索引加锁,在去对应主键索引上加锁
  3. 事务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. 解决问题

已知了问题出现的原因后,有几种方式可以解决该现象

  1. sql中使用force index,强制指定某个索引
  2. 关闭index merge,需要重启实例后生效
  3. 删除index merge时使用的多个索引中的不必要的索引

这里为了快速验证,所以选择了第一种方式,直接修改了sql,在观察一段时间后没有再出现慢sql和死锁情况。

后续根据SQL使用情况,酌情修改优化索引。

三. 总结

这次事故产生了大量的慢SQL,在排除了多种情况后,通过日志确定是由于锁竞争产生了死锁,导致后续sql的等待时间过多而产生。

虽然导致死锁的原因是由index merge优化策略产生,但是究其根本是因为索引创建的不合理,并且这种情况很隐晦,数据量上涨且索引的数据样本产生倾斜后,才爆发出来。

所以,在操作数据和建立索引时,应当做到以下几点

  1. 同组资源按照相同的顺序访问,避免产生死锁的概率
  2. 尽量不要为sql使用的每字段分别建立单独索引,结合使用场景和最左前缀匹配原则正确的建立联合索引(多列索引)
  3. 有必要时可以使用force index(也许不太优雅),毕竟MySQL的优化器也有不靠谱的时候
  4. 脑海里要有sql执行的整个流程,在操作数据表和排查问题的时候,思考是否有分支会存在问题
分类:
后端
标签:
收藏成功!
已添加到「」, 点击更改