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以及其他的一些参数,尽量让这种情况发生的概率降低。                            


posted @ 2017-10-25 16:25  newbelee  阅读(2626)  评论(0编辑  收藏  举报