sqle icon indicating copy to clipboard operation
sqle copied to clipboard

Published 20 hours ago • verified publisher icon actiontech

多扫描任务时有概率出现死锁情况

Open HuangWeiCen opened this issue 2 years ago • 2 comments

复现情况

不稳定复现, 但看日志频率挺高

问题环境

有两个扫描任务的SQLE image

问题日志

std d4b62b47-d27a-48d4-90b1-74f528b1e1fb

sqled.log 日志太大放不下, 也没啥有效信息, 截几张图

(grep 1213) image

(报错上下三十行) image

预期

不应该出现死锁

HuangWeiCen avatar Dec 09 '22 02:12 HuangWeiCen

MySQL死锁日志

new | InnoDB | |

2022-12-08 08:22:12 0x7f4f0011a700 INNODB MONITOR OUTPUT

Per second averages calculated from the last 3 seconds

BACKGROUND THREAD

srv_master_thread loops: 462 srv_active, 0 srv_shutdown, 85448 srv_idle srv_master_thread log flush and writes: 85910

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 7442 OS WAIT ARRAY INFO: signal count 13054 RW-shared spins 0, rounds 33876, OS waits 3801 RW-excl spins 0, rounds 63949, OS waits 586 RW-sx spins 583, rounds 10913, OS waits 157 Spin rounds per wait: 33876.00 RW-shared, 63949.00 RW-excl, 18.72 RW-sx

LATEST DETECTED DEADLOCK

2022-12-08 08:18:31 0x7f4f0019e700 *** (1) TRANSACTION: TRANSACTION 95148, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 5 lock struct(s), heap size 1136, 36 row lock(s), undo log entries 15 MySQL thread id 346, OS thread handle 139977281382144, query id 58724 20.20.20.1 root update INSERT INTO audit_plan_sqls_v2 (audit_plan_id,fingerprint_md5, fingerprint, sql_content, info) VALUES (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?) *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 419 page no 5 n bits 248 index uniq_audit_plan_sqls_v2_audit_plan_id_fingerprint_md5 of table sqle.audit_plan_sqls_v2 trx id 95148 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 90 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 316439653265363563323735666464396336653063313337306564376331; asc 1d9e2e65c275fdd9c6e0c1370ed7c1; (total 32 bytes); 2: len 4; hex 00034f0f; asc O ;;

*** (2) TRANSACTION: TRANSACTION 95147, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 4 lock struct(s), heap size 1136, 33 row lock(s), undo log entries 20 MySQL thread id 345, OS thread handle 139977280841472, query id 58723 20.20.20.1 root update INSERT INTO audit_plan_sqls_v2 (audit_plan_id,fingerprint_md5, fingerprint, sql_content, info) VALUES (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?), (?, ?, ?, ?, ?) *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 419 page no 5 n bits 248 index uniq_audit_plan_sqls_v2_audit_plan_id_fingerprint_md5 of table sqle.audit_plan_sqls_v2 trx id 95147 lock mode S locks gap before rec Record lock, heap no 18 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 653162373235336563343038613361316537643534643639323436633963; asc e1b7253ec408a3a1e7d54d69246c9c; (total 32 bytes); 2: len 4; hex 00034f17; asc O ;;

Record lock, heap no 20 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 663337363463663237633036393763663530323466613330323761633063; asc f3764cf27c0697cf5024fa3027ac0c; (total 32 bytes); 2: len 4; hex 00034f19; asc O ;;

Record lock, heap no 23 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 623733656332343061336335373962396436306538333533393139356164; asc b73ec240a3c579b9d60e83539195ad; (total 32 bytes); 2: len 4; hex 00034f15; asc O ;;

Record lock, heap no 31 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 396530633961363731626332306536386362666637393137373465636137; asc 9e0c9a671bc20e68cbff791774eca7; (total 32 bytes); 2: len 4; hex 00034f18; asc O ;;

Record lock, heap no 38 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 663132333833386361626439653535323161333735636632393031373266; asc f123838cabd9e5521a375cf290172f; (total 32 bytes); 2: len 4; hex 00034f0e; asc O ;;

Record lock, heap no 80 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 363333373532636535353632636630383638626636386439666263333332; asc 633752ce5562cf0868bf68d9fbc332; (total 32 bytes); 2: len 4; hex 00034f10; asc O ;;

Record lock, heap no 81 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 646338643436636164333731373139356634623539353034646566363864; asc dc8d46cad3717195f4b59504def68d; (total 32 bytes); 2: len 4; hex 00034f1b; asc O ;;

Record lock, heap no 82 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 393063353264633337616334653339323833646461336636353138353736; asc 90c52dc37ac4e39283dda3f6518576; (total 32 bytes); 2: len 4; hex 00034f1d; asc O ;;

Record lock, heap no 90 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 316439653265363563323735666464396336653063313337306564376331; asc 1d9e2e65c275fdd9c6e0c1370ed7c1; (total 32 bytes); 2: len 4; hex 00034f0f; asc O ;;

Record lock, heap no 103 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 333261303162363638646136313164393031623435396336363762633462; asc 32a01b668da611d901b459c667bc4b; (total 32 bytes); 2: len 4; hex 00034f0d; asc O ;;

Record lock, heap no 111 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 336263646438663233363635623664383033303233663730373533613131; asc 3bcdd8f23665b6d803023f70753a11; (total 32 bytes); 2: len 4; hex 00034f0c; asc O ;;

Record lock, heap no 112 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 656233636165623736383865633430653261326666346164643066363339; asc eb3caeb7688ec40e2a2ff4add0f639; (total 32 bytes); 2: len 4; hex 00034f0b; asc O ;;

Record lock, heap no 116 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 616561336565393932643762306539343265636662646230346230333638; asc aea3ee992d7b0e942ecfbdb04b0368; (total 32 bytes); 2: len 4; hex 00034f1a; asc O ;;

Record lock, heap no 122 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 653139666133613635326333653638346635366264323334386537376264; asc e19fa3a652c3e684f56bd2348e77bd; (total 32 bytes); 2: len 4; hex 00034f16; asc O ;;

Record lock, heap no 135 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 323636386233323562313636353361333862353765343734353065633663; asc 2668b325b16653a38b57e47450ec6c; (total 32 bytes); 2: len 4; hex 00034f1c; asc O ;;

Record lock, heap no 144 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 646561376563613661346534356165393033616664323666623330633664; asc dea7eca6a4e45ae903afd26fb30c6d; (total 32 bytes); 2: len 4; hex 00034f14; asc O ;;

Record lock, heap no 167 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 356639353632396362626536386235636238656665356462353630313961; asc 5f95629cbbe68b5cb8efe5db56019a; (total 32 bytes); 2: len 4; hex 00034f12; asc O ;;

Record lock, heap no 168 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 363065623032643433316635323233356331636235636331356635393734; asc 60eb02d431f52235c1cb5cc15f5974; (total 32 bytes); 2: len 4; hex 00034f13; asc O ;;

Record lock, heap no 174 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 376238333137616232623032373665623039373033316239636566663666; asc 7b8317ab2b0276eb097031b9ceff6f; (total 32 bytes); 2: len 4; hex 00034f11; asc O ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 419 page no 5 n bits 248 index uniq_audit_plan_sqls_v2_audit_plan_id_fingerprint_md5 of table sqle.audit_plan_sqls_v2 trx id 95147 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 90 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 00000002; asc ;; 1: len 30; hex 316439653265363563323735666464396336653063313337306564376331; asc 1d9e2e65c275fdd9c6e0c1370ed7c1; (total 32 bytes); 2: len 4; hex 00034f0f; asc O ;;

*** WE ROLL BACK TRANSACTION (1)

TRANSACTIONS

Trx id counter 95194 Purge done for trx's n:o < 95194 undo n:o < 0 state: running but idle History list length 6 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421452620324496, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421452620323576, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421452620322656, not started 0 lock struct(s), heap size 1136, 0 row lock(s)

FILE I/O

I/O thread 0 state: waiting for completed aio requests (insert buffer thread) I/O thread 1 state: waiting for completed aio requests (log thread) I/O thread 2 state: waiting for completed aio requests (read thread) I/O thread 3 state: waiting for completed aio requests (read thread) I/O thread 4 state: waiting for completed aio requests (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] , ibuf aio reads:, log i/o's:, sync i/o's: Pending flushes (fsync) log: 0; buffer pool: 0 874 OS file reads, 16353 OS file writes, 6557 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 0, seg size 2, 0 merges merged operations: insert 0, delete mark 0, delete 0 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 34679, node heap has 0 buffer(s) Hash table size 34679, node heap has 1 buffer(s) Hash table size 34679, node heap has 1 buffer(s) Hash table size 34679, node heap has 1 buffer(s) Hash table size 34679, node heap has 2 buffer(s) Hash table size 34679, node heap has 1 buffer(s) Hash table size 34679, node heap has 1 buffer(s) Hash table size 34679, node heap has 1 buffer(s) 0.00 hash searches/s, 0.67 non-hash searches/s

LOG

Log sequence number 635364932 Log flushed up to 635364932 Pages flushed up to 635364932 Last checkpoint at 635364923 0 pending log flushes, 0 pending chkp writes 3896 log i/o's done, 0.00 log i/o's/second

BUFFER POOL AND MEMORY

Total large memory allocated 137428992 Dictionary memory allocated 435560 Buffer pool size 8192 Free buffers 7434 Database pages 750 Old database pages 286 Modified db pages 0 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 623, created 127, written 11709 0.00 reads/s, 0.00 creates/s, 0.00 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 750, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0]

ROW OPERATIONS

0 queries inside InnoDB, 0 queries in queue 0 read views open inside InnoDB Process ID=1, Main thread ID=139977203640064, state: sleeping Number of rows inserted 50917, updated 184, deleted 15444, read 100449 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 5.00 reads/s

END OF INNODB MONITOR OUTPUT

HuangWeiCen avatar Dec 09 '22 02:12 HuangWeiCen

初步分析

备注

发现问题时进行的简单排查和结论推断, 仅作参考

问题分析

通过死锁日志可以看出, 有两个不同的事务正在尝试同时对 audit_plan_sqls_v2 表进行操作，并且它们之间存在冲突。具体来说，第一个事务正在执行一个插入操作，而第二个事务也正在执行插入操作，并且它们都需要对表上的同一条记录加锁才能完成操作。

由于 MySQL 使用行级锁定，因此只有一个事务能够获得锁定，另一个事务必须等待锁定被释放后才能继续运行。在这种情况下，第一个事务在等待第二个事务释放锁定，而第二个事务可能正在等待第一个事务释放锁定。此时就出现了现在这个问题

两个插入操作首先锁定了不同的行，然后又锁定了对方锁定的行，导致它们互相等待对方释放锁定。

举个例子，假设第一个插入操作试图插入表中的行 1，并获得了对该行的锁定。第二个插入操作也试图插入表中的行 1，但由于第一个插入操作已经锁定了该行，因此第二个插入操作必须等待锁定被释放。

同时，第二个插入操作还试图插入表中的行 2，并获得了对该行的锁定。第一个插入操作也试图插入表中的行 2，但由于第二个插入操作已经锁定了该行，因此第一个插入操作也必须等待锁定被释放。

这样一来，第一个插入操作在等待第二个插入操作释放锁定。同样，第二个插入操作也在等待第一个插入操作释放锁定。因此，两个插入操作都无法继续执行，导致死锁。

解决方案

将批量插入改为单条插入, 或将并发插入改为线性插入应该可以解决这问题

HuangWeiCen avatar Dec 09 '22 02:12 HuangWeiCen