pt-osc死鎖分析

1、某天上線前，看一下上線的SQL列表，發現有一個SQL需要對大表(三千萬左右記錄)增加一個字段，這個表24小時都會有業務使用，只有晚上的時候操作沒那么頻繁。為了降低對業務的影響，決定使用pt-online-schema-change工具進行更新表結構。

pt-online-schema-change：是對大表進行在線alter操作，並盡量避免影響線上業務，這是最優秀的mysql管理工作之一，平常運維中使用也比較多。

(1)發生環境：

percona-toolkit ：3.0.4
mysql:5.6.27-log
isolation：Read committed

(2)問題描述：

pt-online-schema-change工具跑完對表結構更改后，第二天開發就過來說幫忙查下昨晚十一點左右線上數據庫怎么回事，從應用報錯看，這個點前后半個小時左右應用報了三四千次死鎖，業務那邊都開始罵人了。

(3)error log

    聽到開發說后，馬上對mysql error(建議開啟每次死鎖都記錄到error log)進行分析，死鎖內容如下：

*** (1) TRANSACTION:
TRANSACTION 164993957148, ACTIVE 3 sec setting auto-inc lock
mysql tables in use 2, locked 2
LOCK WAIT 6 lock struct(s), heap size 1184, 3 row lock(s)
MySQL thread id 189071372, OS thread handle 0x7f9e5e82d700, query id 310630851540 10.10.168.169 prodect_user update
REPLACE INTO `pppppp_ccc`.`_t_good_price_new` (`gid`,`price`,`shop_id`,`updatetime`,...) VALUES (`NEW.gid`,`NEW.price`,`NEW.shop_id`,`NEW.updatetime`,...)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `pppppp_ccc`.`_t_good_price_new` trx id 164993957148 lock mode AUTO-INC waiting

*** (2) TRANSACTION:
TRANSACTION 164993956744, ACTIVE 3 sec fetching rows
mysql tables in use 2, locked 2
53 lock struct(s), heap size 6544, 4024 row lock(s), undo log entries 3481
MySQL thread id 189078502, OS thread handle 0x7f9e539e7700, query id 310630850764 10-10-8-8 10.10.168.168 pt_user Sending data
INSERT LOW_PRIORITY IGNORE INTO `pppppp_ccc`.`_t_good_price_new` (`gid`,`price`,`shop_id`,`updatetime`,...) SELECT `gid`,`price`,`shop_id`,`updatetime`,... FROM `pppppp_ccc`.`t_good_price` FORCE INDEX(`PRIMARY`) WHERE ((`gid` >= '32081571')) AND ((`gid` <= '32087240')) LOCK IN SHARE MODE /*pt-online-schema-change 19391 copy nibble*/
*** (2) HOLDS THE LOCK(S):
TABLE LOCK table `pppppp_ccc`.`_t_good_price_new` trx id 164993956744 lock mode AUTO-INC
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2905 page no 349991 n bits 224 index `PRIMARY` of table `pppppp_ccc`.`t_good_price` trx id 164993956744 lock mode S locks rec but not gap waiting
Record lock, heap no 109 PHYSICAL RECORD: n_fields 22; compact format; info bits 0
 
*** WE ROLL BACK TRANSACTION (1)
2017-10-23 23:06:27 7f9e539e7700InnoDB: transactions deadlock detected, dumping detailed information.

2、分析

    根據死鎖信息可以得到 2個信息：

(1)事務一在等待"_t_good_price_new"表的AUTO-INC表鎖；

(2)事務2獲得了"_t_good_price_new"的AUTO-INC表鎖，等待"t_good_price"的記錄鎖。

    MySQL的死鎖信息記錄不詳細，僅僅由上面的兩個SQL，根本不會造成死鎖，那么只能找出整個事務到底有哪些SQL組成的，以及順序是怎樣的。

    事務1的replace into語句，明顯是跑pt-osc創建的觸發器產生的，當原表產生記錄更新時，觸發器並將記錄以replace方式同步到新表，那么這樣的情況有沒有出現上述的死鎖呢？答案是有的。

事務1：
(1)t_good_price根據條件更新，對t_good_price持有排他的RECORD LOCKS；
(2)更新后觸發器被觸發，再以replace的方式插入_t_good_price_new表，需要對_t_good_price_new持有一個隱式的自增鎖。

事務2：
(1)由上一篇文章中可以知道，insert into select from 的加鎖順序，事務2首先對_t_good_price_new加上了表級的自增鎖；
(2)對新表加上表鎖后，再根據條件中主鍵id的范圍區間去申請原表t_good_price的記錄鎖。

　 由上，由於事務1先更新原表t_good_price，對更新的記錄加上排它鎖，觸發器還沒觸發時，事務2開始執行，這個時候事務2現對新表加表鎖，當它再去申請對原表加記錄級別的共享鎖時，發現部分記錄被加上了排他鎖，所以需要等待。這時事務1觸發器觸發了，需要對新表獲取一個自增鎖，造成了回環，產生死鎖。

事務1：
            持有：t_good_price表記錄上的x鎖
            等待：_t_good_price_new 表上的auto-inc lock
事務2：
            持有：_t_good_price_new 表上的auto-inc lock
            等待：t_good_price 表上的記錄的S鎖

    以上成立的條件是：事務1更新的記錄剛好是事務2需要加S鎖的，這樣就成了完美的死鎖。

    結合我們業務，由於當時需要對很多商品價格進行修改，也是批量操作，於是出現了以上的事情，有興趣的，可以繼續做以下的測試重現下。

3、重現　

 (1)准備條件：

(1)建表
create table test_deadlock (id int auto_increment primary key,name varchar(10));
(2)插入數據
insert into test_deadlock select null,'張三';
insert into test_deadlock select null,'李四';
insert into test_deadlock select null,'王五';
insert into test_deadlock select null,'陳六';
insert into test_deadlock select null,'田七';
(3)建新表，模擬pt
create table  _test_deadlock_new like test_deadlock;
alter table _test_deadlock_new add column age int default null;
(4)建觸發器，這里只建更新的，模擬pt，由於記錄少，更新很快，所以在觸發器觸發時sleep 5s，增加可操作時間
delimiter //
create trigger  pt_osc_test_test_deadlock_upd  after update on test.test_deadlock for  each row  begin  declare x int; set x = sleep(5); delete  IGNORE from  test._test_deadlock_new  where  !(OLD.`id` <=> NEW.`id`) and  test._test_deadlock_new.id  <=> OLD.`id`;replace into test._test_deadlock_new  (`id`, `name`)  values  (NEW.`id`, NEW.`name`);END//
delimiter ;
(5)表中數據

mysql> select * from test_deadlock;
+----+--------+
| id | name |
+----+--------+
| 1 | 張三 |
| 2 | 李四 |
| 3 | 王五 |
| 4 | 陳六 |
| 5 | 田七 |
+----+--------+

(2)操作步驟：

session 1：

begin;
update test_deadlock set name = '陳皮' where id = 4;

session 2（注意，需在5s內操作）：

begin;
insert into _test_deadlock_new(id,name) select id,name from test_deadlock where id > 2 and id <5 lock in share mode;

    5s鍾一到，session 1便會報錯，信息如下：

mysql> update test_deadlock set name = '陳皮' where id = 4;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

    鎖信息如下：

*** (1) TRANSACTION:
TRANSACTION 1880306, ACTIVE 1 sec fetching rows
mysql tables in use 2, locked 2
LOCK WAIT 5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 3342, OS thread handle 0x7f209e5e0700, query id 3056466 localhost root Sending data
insert into _test_deadlock_new(id,name) select id,name from test_deadlock where id > 2 and id <5 lock in share mode
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1642 page no 3 n bits 72 index `PRIMARY` of table `test`.`test_deadlock` trx id 1880306 lock mode S locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000004; asc     ;;
 1: len 6; hex 0000001cb0f1; asc       ;;
 2: len 7; hex 120000271805ca; asc    '   ;;
 3: len 6; hex e99988e79aae; asc       ;;

*** (2) TRANSACTION:
TRANSACTION 1880305, ACTIVE 5 sec setting auto-inc lock, thread declared inside InnoDB 5000
mysql tables in use 2, locked 2
4 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 2
MySQL thread id 3341, OS thread handle 0x7f209f59e700, query id 3056468 localhost root update
replace into test._test_deadlock_new  (`id`, `name`)  values  (NEW.`id`, NEW.`name`)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1642 page no 3 n bits 72 index `PRIMARY` of table `test`.`test_deadlock` trx id 1880305 lock_mode X locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000004; asc     ;;
 1: len 6; hex 0000001cb0f1; asc       ;;
 2: len 7; hex 120000271805ca; asc    '   ;;
 3: len 6; hex e99988e79aae; asc       ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test`.`_test_deadlock_new` trx id 1880305 lock mode AUTO-INC waiting
*** WE ROLL BACK TRANSACTION (2)
------------

    有興趣的可以研究下，所以執行pt-osc時在繁忙的服務器上也是有風險的。比如我們遇到的這種情況，剛好insert到新表的記錄同時也是業務更新的數據，雖然概率很低，但是也會存在這樣的情況。使用時也可以通過--chunk-size以及其他的一些參數，盡量讓這種情況發生的概率降低。