生产环境下的一个死锁分析
首先是系统打印日志
06:17:29.255 [http-nio-9055-exec-3] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Before request [uri=/childOrder/ModifiyChildOrderStatusDelivering]
06:17:29.256 [http-nio-9055-exec-3] INFO c.k.c.b.m.MultiTenantConnectionProvider - 租户信息saturn_titan_x
06:17:29.273 [http-nio-9055-exec-7] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Before request [uri=/childOrder/ModifiyChildOrderStatusDelivering]
06:17:29.273 [http-nio-9055-exec-7] INFO c.k.c.b.m.MultiTenantConnectionProvider - 租户信息saturn_titan_x
06:17:29.313 [http-nio-9055-exec-7] WARN o.h.e.jdbc.spi.SqlExceptionHelper - SQL Error: 1213, SQLState: 40001
06:17:29.313 [http-nio-9055-exec-7] ERROR o.h.e.jdbc.spi.SqlExceptionHelper - Deadlock found when trying to get lock; try restarting transaction
06:17:29.320 [http-nio-9055-exec-7] ERROR c.k.c.b.c.GlobleExceptionHandler - could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
at com.kuding.order.services.ChildOrderService.lambda$modifyChildOrderDeliverStatus$23(ChildOrderService.java:423)
at com.kuding.order.services.ChildOrderService.modifyChildOrderDeliverStatus(ChildOrderService.java:416)
at com.kuding.order.controllers.ChildOrderController.modifyDeliveringStatus(ChildOrderController.java:68)
at com.kuding.common.basestructure.filters.GeetestFilter.doFilter(GeetestFilter.java:102)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
at com.kuding.common.basestructure.interfaces.daointerfacesv2.AbstractDao.create(AbstractDao.java:22)
Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
06:17:29.321 [http-nio-9055-exec-7] INFO c.k.c.b.m.MultiTenantConnectionProvider - 租户信息saturn_titan_x
06:17:29.321 [http-nio-9055-exec-7] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - After request [uri=/childOrder/ModifiyChildOrderStatusDelivering;payload=childOrderId=18238]
06:17:29.330 [http-nio-9055-exec-3] INFO c.k.c.b.m.MultiTenantConnectionProvider - 租户信息saturn_titan_x
06:17:29.330 [http-nio-9055-exec-3] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - After request [uri=/childOrder/ModifiyChildOrderStatusDelivering;payload=childOrderId=18238]查看数据库中的死锁日志
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-03-09 06:17:29 0x7f7562288700
*** (1) TRANSACTION:
TRANSACTION 15755939, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 11 lock struct(s), heap size 1136, 24 row lock(s), undo log entries 24
MySQL thread id 969787, OS thread handle 140142136055552, query id 85203438 10.31.63.50 saas_titanteam updating
update purchase_cell_inventory_info set inventory_count=-26.0 where id=26
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 7481 page no 7 n bits 288 index PRIMARY of table `saturn_titan_x`.`purchase_cell_inventory_info` trx id 15755939 lock_mode X locks rec but not gap waiting
Record lock, heap no 19 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 800000000000001a; asc ;;
1: len 6; hex 000000f024ac; asc $ ;;
2: len 7; hex 240000023c0b80; asc $ < ;;
3: SQL NULL;
4: len 8; hex 8000000000000182; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 00000000000035c0; asc 5 ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
*** (2) TRANSACTION:
TRANSACTION 15755940, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 8 row lock(s), undo log entries 8
MySQL thread id 969834, OS thread handle 140142134724352, query id 85203444 10.31.63.50 saas_titanteam update
insert into warehouse_inventory_log (augmenter, count, create_time, operation_user_id, inventory_id, message, directory, purchase_cell_id, type) values (5.6, -15.8, '2019-03-09 06:17:29.306', 27, 5, '广东菜心 销售出库', 1, 364, 3)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 7481 page no 7 n bits 288 index PRIMARY of table `saturn_titan_x`.`purchase_cell_inventory_info` trx id 15755940 lock mode S locks rec but not gap
Record lock, heap no 19 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 800000000000001a; asc ;;
1: len 6; hex 000000f024ac; asc $ ;;
2: len 7; hex 240000023c0b80; asc $ < ;;
3: SQL NULL;
4: len 8; hex 8000000000000182; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 00000000000035c0; asc 5 ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 20 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 800000000000001b; asc ;;
1: len 6; hex 000000f024ac; asc $ ;;
2: len 7; hex 240000023c0baa; asc $ < ;;
3: SQL NULL;
4: len 8; hex 8000000000000183; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 00000000000020c0; asc ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 48 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 800000000000003b; asc ;;;
1: len 6; hex 000000f00787; asc ;;
2: len 7; hex 24000004371cc3; asc $ 7 ;;
3: SQL NULL;
4: len 8; hex 80000000000001a5; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex cdcccccccccc35c0; asc 5 ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 68 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 8000000000000052; asc R;;
1: len 6; hex 000000f0245a; asc $Z;;
2: len 7; hex 5a000004dd174a; asc Z J;;
3: SQL NULL;
4: len 8; hex 80000000000001d4; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 6666666666e638c0; asc fffff 8 ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 97 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 800000000000007b; asc {;;
1: len 6; hex 000000f053ec; asc S ;;
2: len 7; hex 24000004c508d7; asc $ ;;
3: SQL NULL;
4: len 8; hex 800000000000020e; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 9a99999999598ac0; asc Y ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 107 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 8000000000000087; asc ;;
1: len 6; hex 000000f03dfc; asc = ;;
2: len 7; hex 320000018d121a; asc 2 ;;
3: SQL NULL;
4: len 8; hex 800000000000021e; asc ;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 6666666666a64ac0; asc fffff J ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
Record lock, heap no 121 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 8000000000000099; asc ;;
1: len 6; hex 000000f053cc; asc S ;;
2: len 7; hex 74000001791b9a; asc t y ;;
3: SQL NULL;
4: len 8; hex 8000000000000232; asc 2;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 6666666666ae88c0; asc fffff ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 7481 page no 7 n bits 288 index PRIMARY of table `saturn_titan_x`.`purchase_cell_inventory_info` trx id 15755940 lock mode S locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
0: len 8; hex 8000000000000005; asc ;;
1: len 6; hex 000000f06aa3; asc j ;;
2: len 7; hex 43000004d12f83; asc C / ;;
3: SQL NULL;
4: len 8; hex 800000000000016c; asc l;;
5: len 8; hex 8000000000000006; asc ;;
6: len 8; hex 9a99999999992fc0; asc / ;;
7: len 8; hex 0000000000000000; asc ;;
8: len 4; hex 80000000; asc ;;
9: SQL NULL;
10: len 4; hex 5a1ba685; asc Z ;;
11: len 1; hex 00; asc ;;
*** WE ROLL BACK TRANSACTION (2)
关于死锁日志的几点说明:
1. 每个事务下的sql语句代表当前被阻塞的sql
2. Record lock, heap no 19 PHYSICAL RECORD 代表了一个行锁,即锁定了no19这个数据行, 这里事务二共有7个行锁,且是s锁
3. 事务一持有的锁需要自己分析, 死锁日志没有相关信息
示例产生的死锁分析: 死锁产生的主要原因是插入操作时对外键关联的数据会加上s锁,(因为要通过当前读检查外键关联是否存在)
事务一事务二交错处理数据, 已经处理完的数据锁未释放,锁相互持有
