MySQL鎖阻塞分析

KyunraWang 2017-10-21

展開全文

日常維護中，經(jīng)常會碰到線程被阻塞，導致數(shù)據(jù)庫響應非常慢，下面就看看如何獲取是哪個線程導致了阻塞的。

blog地址：http://blog.csdn.net/hw_libo/article/details/39080809

1. 環(huán)境說明

RHEL 6.4 x86_64 + MySQL 5.6.19
事務隔離級別：RR

2. 測試過程

3. 查看鎖阻塞線程信息

這里用幾中方法進行分析：

3.1 使用show processlist查看

[sql] view plaincopy
 print?
MySQL [(none)]> show processlist;  
+----+------+-----------+------+---------+------+--------------+------------------------------------------+  
| Id | User | Host      | db   | Command | Time | State        | Info                                     |  
+----+------+-----------+------+---------+------+--------------+------------------------------------------+  
|  2 | root | localhost | NULL | Query   |    0 | init         | show processlist                         |  
|  3 | root | localhost | test | Query   |   70 | Sending data | select count(*) from t3 a,t3 b           |  
|  4 | root | localhost | test | Query   |   65 | updating     | delete from emp where empno=7788         |  
|  7 | root | localhost | test | Query   |   68 | updating     | update emp set sal=3500 where empno=7788 |  
+----+------+-----------+------+---------+------+--------------+------------------------------------------+  
4 rows in set (0.00 sec)  

如果數(shù)據(jù)庫存在較多線程的話，這種方法確實不太好確認的。

3.2 直接使用show engine innodb status查看

[html] view plaincopy
 print?
------------  
TRANSACTIONS  
------------  
Trx id counter 4131  
Purge done for trx's n:o < 4119 undo n:o < 0 state: running but idle  
History list length 126  
LIST OF TRANSACTIONS FOR EACH SESSION:  
---TRANSACTION 0, not started  
MySQL thread id 2, OS thread handle 0x7f953ffff700, query id 115 localhost root init  
show engine innodb status  
---TRANSACTION 4130, ACTIVE 41 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 4, OS thread handle 0x7f953ff9d700, query id 112 localhost root updating  
delete from emp where empno=7788  
------- TRX HAS BEEN WAITING 41 SEC FOR THIS LOCK TO BE GRANTED:   ## 等待了41s  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4130 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  ## 線程4在等待往test.emp中的主鍵上加X鎖，page num=3  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
------------------  
---TRANSACTION 4129, ACTIVE 45 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 7, OS thread handle 0x7f953ff6c700, query id 111 localhost root updating  
update emp set sal=3500 where empno=7788  
------- TRX HAS BEEN WAITING 45 SEC FOR THIS LOCK TO BE GRANTED:   ## 等待了45s  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4129 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  ## 線程7在等待往test.emp中的主鍵上加X鎖，page num=3  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
------------------  
---TRANSACTION 4128, ACTIVE 51 sec  
2 lock struct(s), heap size 360, 1 row lock(s)  
MySQL thread id 3, OS thread handle 0x7f953ffce700, query id 110 localhost root cleaning up  

我們知道，主要根因還是thread=3引起的，但從innodb status中卻無法分析得到這個結果。

從上面來看，線程4和線程7都在等待往test.emp中的主鍵上加X鎖，page num=3，但是線程7等待的時間為45s，而線程4等待的時間為41s，是較線程7之后申請的鎖，所以可以判斷是線程7阻塞了線程4。至于線程7為什么出現(xiàn)等待，這里分析不到根因。

3.3 使用mysqladmin debug查看

# mysqladmin -S /tmp/mysql3306.sock debug

然后在error日志中，會看到：

[html] view plaincopy
 print?
Thread database.table_name          Locked/Waiting        Lock_type  
  
  
3       test.t3                     Locked - read         Low priority read lock  
7       test.emp                    Locked - write        High priority write lock  

這種方法中，能找到線程ID=3和7是阻塞者，但還是不太準確，判斷不出來線程7也是被線程ID=3阻塞的。

3.4 使用innodb_lock_monitor來獲取阻塞鎖線程

[sql] view plaincopy
 print?
MySQL [test]> CREATE TABLE innodb_lock_monitor (a INT) ENGINE=INNODB;  ## 隨便在一個數(shù)據(jù)庫中創(chuàng)建這個表，就會打開lock monitor  
Query OK, 0 rows affected, 1 warning (0.07 sec)  
  
MySQL [test]> show warnings\G  
*************************** 1. row ***************************  
  Level: Warning  
   Code: 131  
Message: Using the table name innodb_lock_monitor to enable diagnostic output is deprecated and may be removed in future releases. Use INFORMATION_SCHEMA or PERFORMANCE_SCHEMA tables or SET GLOBAL innodb_status_output=ON.  
1 row in set (0.00 sec)  

說明：這個在5.6中有一個warning，但不影響使用。

然后再使用show engine innodb status查看：

[html] view plaincopy
 print?
------------  
TRANSACTIONS  
------------  
Trx id counter 4667  
Purge done for trx's n:o < 4659 undo n:o < 0 state: running but idle  
History list length 138  
LIST OF TRANSACTIONS FOR EACH SESSION:  
---TRANSACTION 0, not started  
MySQL thread id 9, OS thread handle 0x7f813c5f7700, query id 152 localhost root init  
show engine innodb status  
---TRANSACTION 4663, ACTIVE 78 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 4, OS thread handle 0x7f813c628700, query id 149 localhost root updating  
delete from emp where empno=7788  
------- TRX HAS BEEN WAITING 78 SEC FOR THIS LOCK TO BE GRANTED:   ## 等待了78s  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4663 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  ## 線程4在等待往test.emp中的主鍵上加X鎖，page num=3  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
------------------  
TABLE LOCK table `test`.`emp` trx id 4663 lock mode IX   ## 在給主鍵行上加X鎖之前，先要在表上加意向鎖IX  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4663 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
---TRANSACTION 4662, ACTIVE 81 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 7, OS thread handle 0x7f813c5c6700, query id 148 localhost root updating  
update emp set sal=3500 where empno=7788  
------- TRX HAS BEEN WAITING 81 SEC FOR THIS LOCK TO BE GRANTED:  ## 等待了81s  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4662 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  ## 線程7在等待往test.emp中的主鍵上加X鎖，page num=3  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
------------------  
TABLE LOCK table `test`.`emp` trx id 4662 lock mode IX   ## 在給主鍵行上加X鎖之前，先要在表上加意向鎖IX  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4662 lock_mode X locks rec but not gap waiting  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  
  
---TRANSACTION 4615, ACTIVE 1579 sec, thread declared inside InnoDB 1222  
mysql tables in use 2, locked 0  
2 lock struct(s), heap size 360, 1 row lock(s)  
MySQL thread id 3, OS thread handle 0x7f813c659700, query id 147 localhost root Sending data  
select count(*) from t3 a,t3 b   ## 這是線程3當前正在執(zhí)行的SQL  
Trx read view will not see trx with id >= 4662, sees < 4659  
TABLE LOCK table `test`.`emp` trx id 4615 lock mode IX  ## 線程3中正在擁有表上的意向IX鎖，并且有test.emp表上主鍵的行級X鎖，page num=3  
RECORD LOCKS space id 16 page no 3 n bits 88 index `PRIMARY` of table `test`.`emp` trx id 4615 lock_mode X locks rec but not gap  
Record lock, heap no 9 PHYSICAL RECORD: n_fields 10; compact format; info bits 0  
 0: len 4; hex 80001e6c; asc    l;;  
 1: len 6; hex 000000001018; asc       ;;  
 2: len 7; hex 91000001420084; asc     B  ;;  
 3: len 5; hex 53434f5454; asc SCOTT;;  
 4: len 7; hex 414e414c595354; asc ANALYST;;  
 5: len 4; hex 80001d8e; asc     ;;  
 6: len 4; hex 208794f0; asc     ;;  
 7: len 4; hex 80000bb8; asc     ;;  
 8: SQL NULL;  
 9: len 4; hex 80000014; asc     ;;  

為什么線程3當前執(zhí)行的是一個select t3表操作，但卻鎖住了test.emp表上page num=3？
有可能是線程3之前對test.emp表的操作事務沒有及時提交導致。
所以得出：線程3阻塞了線程7，而線程7又阻塞了線程4，所以根因就是線程3，讓線程3盡快提交或是kill掉即可。

4. 結論

在分析innodb中鎖阻塞時，幾種方法的對比情況：

（1）使用show processlist查看不靠譜；
（2）直接使用show engine innodb status查看，無法判斷到問題的根因；
（3）使用mysqladmin debug查看，能看到所有產生鎖的線程，但無法判斷哪個才是根因；
（4）開啟innodb_lock_monitor后，再使用show engine innodb status查看，能夠找到鎖阻塞的根因。