(13)生产环境出现大量DB死锁

1、死锁日志

2018-10-23T07:16:23.919555+08:00 478808 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

2018-10-23T07:16:23.919573+08:00 478808 [Note] InnoDB: 

*** (1) TRANSACTION:

TRANSACTION 638350242, ACTIVE 0 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 18 lock struct(s), heap size 1136, 6 row lock(s), undo log entries 2

MySQL thread id 482727, OS thread handle 139949379430144, query id 1038382163 10.205.72.161 ucp updating

update ccp_order_info_1 set bill_push_status = 1 where partner_id = '80640511' and  order_code in

     (  'UCP181023071619030500' , 'UCP181023071613030491', 'UCP181023071604030490', 'UCP181023071558030489' )

2018-10-23T07:16:23.919607+08:00 478808 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 383 page no 9655 n bits 104 index PRIMARY of table `ccp`.`ccp_order_info_1` /* Partition `p201810` */ trx id 638350242 lock_mode X locks rec but not gap waiting

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

 0: len 8; hex fd67828666135000; asc  g  f P ;;

 1: len 4; hex 5bce5a3d; asc [ Z=;;

 2: len 6; hex 0000260c73a3; asc   & s ;;

 3: len 7; hex 28000000230937; asc (   # 7;;

 4: len 21; hex 554350313831303233303731363133303330343931; asc UCP181023071613030491;;

  ... // 省略后续82个字段的信息

TRANSACTION 638350243, ACTIVE 0 sec fetching rows

mysql tables in use 1, locked 1

14 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1

MySQL thread id 478808, OS thread handle 139949392209664, query id 1038382165 10.205.72.157 ucp updating

UPDATE ccp_order_info_1 SET order_Status=1,error_Flag='1',push_time='2018-10-23 07:16:23.91'  WHERE partner_id = '80640511' And ORDER_ID =         

9036334691091959808

2018-10-23T07:16:23.921748+08:00 478808 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 383 page no 9655 n bits 112 index PRIMARY of table `ccp`.`ccp_order_info_1` /* Partition `p201810` */ trx id 638350243 lock_mode X locks rec but not gap

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

 0: len 8; hex fd67828666135000; asc  g  f P ;;

 1: len 4; hex 5bce5a3d; asc [ Z=;;

 2: len 6; hex 0000260c73a3; asc   & s ;;

 3: len 7; hex 28000000230937; asc (   # 7;;

 4: len 21; hex 554350313831303233303731363133303330343931; asc UCP181023071613030491;;

 ... 省略后面82个字段的信息

2018-10-23T07:16:23.923431+08:00 478808 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 383 page no 9655 n bits 104 index PRIMARY of table `ccp`.`ccp_order_info_1` /* Partition `p201810` */ trx id 638350243 lock_mode X locks rec but not gap waiting

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

 0: len 8; hex fd67a62566135000; asc  g %f P ;;

 1: len 4; hex 5bce5a34; asc [ Z4;;

 2: len 6; hex 0000260c73a2; asc   & s ;;

 3: len 7; hex 27000040030785; asc '  @   ;;

 4: len 21; hex 554350313831303233303731363034303330343930; asc UCP181023071604030490;;

 ... 省略后面82个字段的信息

2018-10-23T07:16:23.925041+08:00 478808 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

上面是两个事物发生死锁的日志,关键日志行分析如下:

1、*** (1) TRANSACTION:第一个事务消息开始。

2、LOCK WAIT 18 lock struct(s), heap size 1136, 6 row lock(s), undo log entries 2

18个锁等待结构体,6行被锁定,事务内已经生成了 2个undo项

3、MySQL thread id 482727, OS thread handle 139949379430144, query id 1038382163 10.205.72.161 ucp updating

mysql中对应的线程ID为482727操作系统线程ID为139949379430144,查询id1038382163 ,线程状态:更新中。

4、update ccp_order_info_1 set bill_push_status = 1 where partner_id = '80640511' and  order_code in  (  'UCP181023071619030500' , 'UCP181023071613030491', 'UCP181023071604030490', 'UCP181023071558030489' )

当前事务SQL,后文也得该语句执行需申请锁而被阻塞

5、2018-10-23T07:16:23.919607+08:00 478808 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

SQL语句中,需要申请的锁(无法立即获取锁信息)

6、RECORD LOCKS space id 383 page no 9655 n bits 112 index PRIMARY of table `ccp`.`ccp_order_info_1` /* Partition `p201810` */ trx id 638350243 lock_mode X locks rec but not gap

需要申请的行锁信息:表空间ID为383,页为9655,在112个字节开始,需要锁定的索引名为(ccp_order_info_1)的主键索引,事务ID为638350243,锁的类型为lock_mode X locks rec but not gap waiting(行级别的排他锁,并不是间隙锁)。

7、Record lock, heap no 32 PHYSICAL RECORD: n_fields 86; compact format; info bits 0

 0: len 8; hex fd67828666135000; asc  g  f P ;;

 1: len 4; hex 5bce5a3d; asc [ Z=;;

 2: len 6; hex 0000260c73a3; asc   & s ;;

 3: len 7; hex 28000000230937; asc (   # 7;;

 4: len 21; hex 554350313831303233303731363133303330343931; asc UCP181023071613030491;;

 ... 省略后面82个字段的信息

请求行锁所对应的物理数据(真实的行数据),从这里也开以看出,这里申请order_no='UCP181023071613030491' 该行数据的行锁。

8、2018-10-23T07:16:23.921701+08:00 478808 [Note] InnoDB: *** (2) TRANSACTION:

接下来看第二个事务的信息,根据上文的分析,事务二在执行的SQL语句为:UPDATE ccp_order_info_1 SET order_Status=1,error_Flag='1',push_time='2018-10-23 07:16:23.91'  WHERE partner_id = '80640511' And ORDER_ID =         9036334691091959808 根据order_id更新1条数据。

9、2018-10-23T07:16:23.921748+08:00 478808 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

记录事务二已持有的锁信息:

10、2018-10-23T07:16:23.921748+08:00 478808 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 383 page no 9655 n bits 112 index PRIMARY of table `ccp`.`ccp_order_info_1` /* Partition `p201810` */ trx id 638350243 lock_mode X locks rec but not gap

发现事务二持有的锁 ,正是事务一急切响应的锁,即order_no=''UCP181023071613030491'的主键索引,即该索引对应的行数据。

11、2018-10-23T07:16:23.923431+08:00 478808 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

显示事务二需要申请的锁。

其主要是申请记录UCP181023071604030490的主键索引,然后mysql立马检测到发生了索引,因为该锁已经被事务1所持有,innodb会选择回滚一个事务,解除死锁,从日志看出,innodb选择将事务二进行回滚。

为什么事务二会去申请记录UCP181023071604030490行锁呢?从哪里可以看出事务1已经持有记录UCP181023071604030490的行锁呢?

死锁日志中,没有事务一中输出事务1当前所持有的行锁,故我们只能从如下信息进行推论:

LOCK WAIT 18 lock struct(s), heap size 1136, 6 row lock(s), undo log entries 2

MySQL thread id 482727, OS thread handle 139949379430144, query id 1038382163 10.205.72.161 ucp updating

update ccp_order_info_1 set bill_push_status = 1 where partner_id = '80640511' and  order_code in

     (  'UCP181023071619030500' , 'UCP181023071613030491', 'UCP181023071604030490', 'UCP181023071558030489' )

undo log entries 2,创建了2个undo条目,猜测两条update,与in中最后两个条目吻合,故认为上述推论可信。第二个问题,为什么事务二会去申请UCP181023071604030490的行锁,应该是事务2中还会有根据order_id去更新UCP181023071604030490该行的SQL语句,与项目组确认代码后分析,确实是有for循环对多条数据进行更新,符合推论,死锁问题得到完成分析。

死锁原因分析:

1、事务1根据order_no(二级索引)更新多条记录,其加锁顺序: 

UCP181023071558030489行:先申请 order_no_index , 再申请 primary_index (主键索引)   申请成功

UCP181023071604030490行:先申请 order_no_index, 再申请 primary_index (主键索引)  申请成功

UCP181023071613030491行:先申请 order_no_index, 再申请 primary_index(主键索引)       order_no_index 申请成功,primary_index 排队等待

UCP181023071619030500行:先申请 order_no_index, 再申请 primary_index(主键索引)

2、事务2是根据主键ID循环来更新多条记录,其加锁顺序为:

UCP181023071613030491行:申请 primary_index(主键索引),然后再申请UCP181023071604030490 的主键索引,事务一,二相互持有各自需要锁,死锁发生。

解决方案:

1、同表更新,用唯一字段更新, 要么order_id ,要么order_no 

2、事务对多个数据更新操作,先集合排序顺序加锁,避免死锁。

Mysql 数据库加锁,可以看看何登成http://hedengcheng.com/?p=771

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

推荐阅读更多精彩内容