MySQL鎖系列（九）之longtransaction

蘭春發表於2017-08-29
MySql

一、背景

最近凌晨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版本
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=`xe7xa6xbbxe8x81x8c` WHERE approve.id = 49384
Aug 29, 2017 10:20:23.589586000    xx.xx.xx.xx    UPDATE approve SET `operator` = `0`,`operator_name` = `system`,`comment` = `xe7xa6xbbxe8x81x8c`,`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診斷問題


相關文章