Contents
  1. 1. 一、背景
  2. 2. 二、环境
  3. 3. 三、分析过程
  4. 4. 四、总结

一、背景

最近凌晨05:00总是接到来自SQL防火墙的告警:

group_name id user host db command time info state
BASE 1059712468 xx xx.xx.xx.xx aea Query 34 UPDATE approve SET operator = ‘0’,operator_name = ‘system’,comment = ‘离职’,status = ‘1’ WHERE (id = ‘48311’) updating

当第一次看到这个数据的时候,第一反应是可能是被受影响的SQL,没话时间关注,但是后面好几次的凌晨告警,就不得不对他进行深入分析

  • 症状特点
  1. 主键更新
  2. 状态为updating
  3. 执行时间30多秒
  4. command为query

这一切看上去都特别正常

二、环境

  • MySQL版本
1
mysql Ver 14.14 Distrib 5.6.16, for linux-glibc2.5 (x86_64) using EditLine wrapper
  • 表结构
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
CREATE TABLE `approve` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`reim_id` int(11) NOT NULL DEFAULT '0' ,
`user_name` varchar(20) NOT NULL DEFAULT '',
`user_ids` varchar(100) NOT NULL DEFAULT '',
`user_email` text COMMENT '用于mail',
`status` tinyint(1) NOT NULL DEFAULT '0' ,
`stagesub` smallint(3) NOT NULL DEFAULT '0' ,
`stage` smallint(3) NOT NULL DEFAULT '0' ,
`flag` tinyint(1) NOT NULL DEFAULT '0' ,
`operator` int(11) NOT NULL DEFAULT '0' ,
`operator_name` varchar(20) NOT NULL DEFAULT '',
`comment` text,
`update_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`cs_userid` int(11) NOT NULL DEFAULT '0' ,
`cs_status` tinyint(4) NOT NULL DEFAULT '0' ,
`is_deficit` tinyint(1) NOT NULL DEFAULT '1' ,
`approve_type` tinyint(4) NOT NULL DEFAULT '1',
PRIMARY KEY (`id`),
KEY `list` (`user_ids`,`status`),
KEY `next` (`flag`,`status`),
KEY `detail` (`reim_id`),
KEY `ix_userid` (`cs_userid`)
) ENGINE=InnoDB AUTO_INCREMENT=464885 DEFAULT CHARSET=utf8

三、分析过程

  • SQL语句本身的分析
1
2
1. 这条语句在正常不过了,而且还是主键更新,执行计划一切都很正常。
2. show processlist中的状态, command=Query,state=updating
  • 手动执行

没有任何问题,瞬间执行完毕

1
2
3
dba> UPDATE approve SET `operator` = '0',`operator_name` = 'system',`comment` = '离职',`status` = '1' WHERE (`id` = '49384');
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
  • 可能的问题原因
1
2
3
4
5
6
7
8
9
10
11
1. SQL语句的拼接问题,会不会凌晨的时候SQL有特殊字符导致的全表扫描更新呢?
1.1 为了这个问题,模拟了N遍,且将所有特殊字符都打印出来,这个问题排除。
2. 服务器压力问题,有没有可能是在凌晨的时候io,cpu压力特别大,造成的updating慢呢?
2.1 查看当时的监控,一切指标都正常,故也排除
3. 数据库本身的问题,MySQL出现bug了?
3.1 这个目前也没有搜到关于这方面的bug 信息
4. 锁的问题,SQL语句当时被锁住了?
4.1 show processlist中没有看到任何lock的字样啊
  • 锁相关排除
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
1. 一开始,所有的故障排除全部来自监控系统和show processlist,然后查看锁的神器没有使用,就是show engine innodb status \G
---TRANSACTION 51055827249, ACTIVE 20 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 1060068541, OS thread handle 0x7fba06c6c700, query id 55990809665 xx aea updating
UPDATE approve SET `operator` = '0',`operator_name` = 'system',`comment` = '离职',`status` = '1' WHERE (`id` = '49384')
------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 746 page no 624 n bits 216 index `PRIMARY` of table `aea`.`approve` trx id 51055827249 lock_mode X locks rec but not gap waiting
Record lock, heap no 148 PHYSICAL RECORD: n_fields 19; compact format; info bits 0
0: len 4; hex 8000c0e8; asc ;;
1: len 6; hex 000be32a10cb; asc * ;;
2: len 7; hex 7a000004540557; asc z T W;;
3: len 4; hex 80002884; asc ( ;;
4: len 6; hex e69da8e58b87; asc ;;
5: len 6; hex 3b363430353b; asc ;6405;;;
6: len 19; hex 7979616e6740616e6a756b65696e632e636f6d; asc yy.com;;
7: len 1; hex 81; asc ;;
8: len 2; hex 8015; asc ;;
9: len 2; hex 8001; asc ;;
10: len 1; hex 80; asc ;;
11: len 4; hex 80000001; asc ;;
12: len 6; hex 73797374656d; asc system;;
13: len 6; hex e7a6bbe8818c; asc ;;
14: len 4; hex 59a4c993; asc Y ;;
15: len 4; hex 80000000; asc ;;
16: len 1; hex 80; asc ;;
17: len 1; hex 81; asc ;;
18: len 1; hex 81; asc ;;
------------------
---TRANSACTION 51055825099, ACTIVE 21 sec
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 1060025172, OS thread handle 0x7fba05ad0700, query id 55990809629 xx aea cleaning up
2. 通过以上片段信息可以得知如下结论
2.1 UPDATE approve 语句等待主键索引的record lock,lock_mode X locks rec but not gap , space id 746 page no 624, 记录为主键49384的row
2.2 TRANSACTION 51055827249, ACTIVE 20 sec , 这个事务持续20
2.3 TRANSACTION 51055825099, ACTIVE 21 sec , 这个事务持续21秒,根据这个信息,很有可能由于这个事务持有UPDATE approve需要的record lock
2.4 TRANSACTION 51055825099, 1 row lock(s) , 根据这个信息,可以更进一步推论出该事务,该thread id 1060025172 持有该记录锁。
3. 很可惜,并不知道是什么SQL语句,说明已经执行完毕
  • 验证
1
2
3
4
5
6
1. 如何验证上面的推论呢?
2. 如何找到是哪条SQL持有锁呢?
3. 首先我们从表入手,查找该表有哪些写入SQL?
通过Performance Schema ,发现了两种形迹可疑的SQL
digest sql count db dbgroup date
0c95e7f2105d7a3e655b8b4462251bf2 UPDATE approve SET operator = ? , operator_name = ? , comment = ? , status = ? WHERE ( id = ? ) 15 xx BASE 20170829
591226ca0ece89fe74bc6894ad193d71 UPDATE approve SET STATUS = ? , operator = ? , operator_name = ? , COMMENT = ? WHERE approve . id = ? 15 xx BASE 20170829
  • 进一步验证
1
2
3
4
5
6
7
8
9
10
11
12
13
14
1. 通过上述SQL,如果他们更新的是同一个id,那么很有可能就会导致锁等待。
2. 要满足上面的推测,还必须满足一个必要条件就是:下面那个语句必须在上面语句之前执行,且没有commit
3. 我们去服务器上进行tcpdump抓包发现如下:
Capturing on Pseudo-device that captures on all interfaces
Aug 29, 2017 10:20:23.560491000 xx.xx.xx.xx UPDATE approve SET status=1, operator=1, operator_name='system', comment='\xe7\xa6\xbb\xe8\x81\x8c' WHERE approve.id = 49384
Aug 29, 2017 10:20:23.589586000 xx.xx.xx.xx UPDATE approve SET `operator` = '0',`operator_name` = 'system',`comment` = '\xe7\xa6\xbb\xe8\x81\x8c',`status` = '1' WHERE (`id` = '49384')
正好验证我们的推论
4. 手动模拟了这种情况,得到的现象和我们的故障一致,即问题原因以及找到
  • 问题解决
1
2
3
4
5
1. 拿到开发的代码,发现是python的代码,并没有auto_commit的选项
2. 第一个事务并没有结束,没有commit,导致下一个事务在等待锁的资源
3. 为什么需要对同一个记录进行两次更新,这个还需要进一步了解代码和业务

四、总结

1
2
3
4
5
6
7
1. 下次遇到类似问题,可以不用被processlist表面现象所迷惑,善于了解锁机制和锁信息的排查
2. 写代码的时候,尽量做到小事务,一般用auto_commit就好,如果需要显示开启事务,也应该尽量做到用完尽量commit
3. MySQL如果能够再show processlist中直接打印出lock,waiting lock状态会更加的人性化
4.show engine innodb status的时候,为什么看不到是哪个SQL语句持有的锁呢?MySQL如果能够提供这样的信息,可以更加好的帮助DBA诊断问题
Contents
  1. 1. 一、背景
  2. 2. 二、环境
  3. 3. 三、分析过程
  4. 4. 四、总结

幸福,不在于得到的多

而在于计较的少