507
MySQL鎖係列（九）之 long transaction
一、背景
最近淩晨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，沒話時間關注，但是後麵好幾次的淩晨告警，就不得不對他進行深入分析
- 症狀特點
- 主鍵更新
- 狀態為updating
- 執行時間30多秒
- command為query
這一切看上去都特別正常
二、環境
- MySQL版本
mysql Ver 14.14 Distrib 5.6.16, for linux-glibc2.5 (x86_64) using EditLine wrapper
- 表結構
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. show processlist中的狀態， command=Query，state=updating
- 手動執行
沒有任何問題，瞬間執行完畢
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. 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. 一開始，所有的故障排除全部來自監控係統和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. 如何找到是哪條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. 通過上述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. 拿到開發的代碼，發現是python的代碼，並沒有auto_commit的選項
2. 第一個事務並沒有結束，沒有commit，導致下一個事務在等待鎖的資源
3. 為什麼需要對同一個記錄進行兩次更新，這個還需要進一步了解代碼和業務
四、總結
1. 下次遇到類似問題，可以不用被processlist表麵現象所迷惑，善於了解鎖機製和鎖信息的排查
2. 寫代碼的時候，盡量做到小事務，一般用auto_commit就好，如果需要顯示開啟事務，也應該盡量做到用完盡量commit
3. MySQL如果能夠再show processlist中直接打印出lock，waiting lock狀態會更加的人性化
4. 在show engine innodb status的時候，為什麼看不到是哪個SQL語句持有的鎖呢？MySQL如果能夠提供這樣的信息，可以更加好的幫助DBA診斷問題
最後更新：2017-08-29 20:03:11