MYSQL:1213 Deadlock问题排查历程

mark下自己近期在电商开发中遇到的一个问题-数据库死锁及其排查过程。
先抛一个业务报错日志做为这次梳理的开始



上图是我接收到的错误报警,SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction,错误信息显示我们业务中有一条数据库操作遇到了死锁情况。接下来就开始我们的追查之旅。

1.执行“show engine innodb status”获取INNODB引擎当前信息(show engine innodb status 详细介绍

------------------------

LATEST DETECTED DEADLOCK

------------------------

2017-01-04 09:25:17 7f553477d700

*** (1) TRANSACTION:

TRANSACTION 124378994, ACTIVE 0.007 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 4 lock struct(s), heap size 1184, 8 row lock(s), undo log entries 7

LOCK BLOCKING MySQL thread id: 11573556 block 11572504

MySQL thread id 11572504, OS thread handle 0x7f56342fb700, query id 3368968901 10.44.182.0 shzfstore updating

UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15608' AND `quantity` >= '1' limit 1

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378994 lock_mode X locks rec but not gap waiting

Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** (2) TRANSACTION:

TRANSACTION 124378995, ACTIVE 0.004 sec starting index read

mysql tables in use 1, locked 1

3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1

MySQL thread id 11573556, OS thread handle 0x7f553477d700, query id 3368968902 10.172.221.117 shzfstore updating

UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15504' AND `quantity` >= '1' limit 1

*** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap

Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 393 page no 43 n bits 240 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap waiting

Record lock, heap no 81 PHYSICAL RECORD: n_fields 19; compact format; info bits 0

......

*** WE ROLL BACK TRANSACTION (2)

LATEST DETECTED DEADLOCK记录了最近一次的死锁情况。
2017-01-04 09:25:17时间跟我们接收到的报错日志时间吻合。
上面还可以看出两个事务之间发生锁竞争时,给我们留下的部分数据
事务1
UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15608' ANDquantity>= '1' limit 1
事务2
UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15504' ANDquantity>= '1' limit 1
死锁的两个资源均被lock_mode X locks了

最后,mysql给了很重要的一个数据“WE ROLL BACK TRANSACTION (2)” MYSQL回滚了事务2。既然mysql回滚了事务2,那么肯定是事务2的语句触发了死锁,被mysql回滚了,也就是应该为报错日志所记录的那部分。同时,MYSQL执行了事务1,那么事务1的SQL语句肯定被记录在BINLOG中了。

2.查看binlog日志,找出事务1所执行的语句

查找依据:

  • SQL语句,根据LATEST DETECTED DEADLOCK提供的死锁时记录的sql语句。
  • 线程ID(mysql的唯一标识): MySQL thread id 11572504
  • 执行时间(时间线):2017-01-04 09:25:17 7f553477d700

根据以上三个标识,以及BINLOG的起始标志“BEGIN、COMMIT”,几乎可以100%确定事务1所包含的SQL语句。

binlog信息大致如下

#170104  9:25:17 server id 3194178605  end_log_pos 137170469 CRC32 0x1b6559de   Query   thread_id=11572504  exec_time=0 error_code=0
SET TIMESTAMP=1483493117/*!*/;
BEGIN
......
### UPDATE `store_product`.`sku`
### WHERE
###   @1=15504
###   @2=11516
###   @3=0.01
###   @4=120065
###   @5=109433
###   @6=19
### SET
###   @1=15504
###   @2=11516
###   @3=0.01
###   @4=120065
###   @5=109432
###   @6=20
# at 137172557
......
### UPDATE `store_product`.`sku`
### WHERE
###   @1=15608
###   @2=11551
###   @3=0.01
###   @4=120077
###   @5=109426
###   @6=19
### SET
###   @1=15608
###   @2=11551
###   @3=0.01
###   @4=120077
###   @5=109425
###   @6=20
......
COMMIT/*!*/;

3.还原事务2所包含的执行语句

事务1的语句找齐了,接下来找事务2的语句,还记得我们开头提供的报错日志吗,那个日志里也详细记录了发起请求时的参数情况(截图未展示),根据参数和我们处理业务的代码,可以复现事务2所要执行的语句

BEGIN
......
### UPDATE `store_product`.`sku`
### WHERE
###   @1=15608
###   @2=11516
###   @3=0.01
###   @4=120065
###   @5=109433
###   @6=19
### SET
###   @1=15608
###   @2=11516
###   @3=0.01
###   @4=120065
###   @5=109432
###   @6=20
......
### UPDATE `store_product`.`sku`
### WHERE
###   @1=15504
###   @2=11551
###   @3=0.01
###   @4=120077
###   @5=109426
###   @6=19
### SET
###   @1=15504
###   @2=11551
###   @3=0.01
###   @4=120077
###   @5=109425
###   @6=20
......
COMMIT/*!*/;

根据两个事务所执行的sql语句,目前可以还原死锁产生的原因了

4.查看两个事务执行语句的顺序:

顺序 事务1 事务2 说明
1 begin
2 begin
3 UPDATE sku
SET quantity=quantity-'1',
lock_stock=lock_stock+'1',
sys_version=sys_version+1
WHERE id = '15504' AND
quantity >= '1' limit 1
事务1 给 sku表 id 15504记录上 X 锁
4 UPDATE sku
SET quantity=quantity-'1',
lock_stock=lock_stock+'1',
sys_version=sys_version+1
WHERE id = '15608' AND
quantity >= '1' limit 1
事务2 给 sku表 id 15608记录上 X 锁
5 UPDATE sku
SET quantity=quantity-'1',
lock_stock=lock_stock+'1',
sys_version=sys_version+1 WHERE id = '15608' AND
quantity >= '1' limit 1
这里是关键,事务1想给sku表 id 15608上X锁,发现被别人(事务2)上锁了,等待锁释放
6 UPDATE sku
SET quantity=quantity-'1',
lock_stock=lock_stock+'1',
sys_version=sys_version+1
WHERE id = '15504' AND
quantity >= '1' limit 1
事物2打算给sku表id为15504记录上 X 排它锁,发现被其他事务上了,而且此事务居然还在等他提交,这时MYSQL立刻回滚事务2…(php发现MYSQL返回死锁信息,记录该信息到错误日志…发送回滚指令…mysql已经“帮”他回滚了…)
7 执行成功 事务1发现别人的锁释放了,获得X锁,执行成功
8 commit 事务1执行成功,记录binlog日志

解决方案

  • 减小事务中的语句数量
  • 在业务中调整语句的执行顺序,例如可以按照where条件中字段的大小进行一下排序,按照排序后顺序执行,让死锁变为锁等待。

相关补充

  • innodb的行锁,锁的是查询条件中的索引字段,以及索引字段对应的primary key字段
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 202,100评论 5 474
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 84,862评论 2 378
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 148,993评论 0 335
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,309评论 1 272
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,303评论 5 363
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,421评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,830评论 3 393
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,501评论 0 256
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,689评论 1 295
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,506评论 2 318
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,564评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,286评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,826评论 3 305
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,875评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,114评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,705评论 2 348
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,269评论 2 341

推荐阅读更多精彩内容