[MDEV-29187] Deadlock output in InnoDB status always shows transaction (0) Created: 2022-07-28  Updated: 2022-07-28  Resolved: 2022-07-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.6.9, 10.7.5, 10.8.4, 10.9.2, 10.10.1

Type: Bug Priority: Major
Reporter: Agustin Assignee: Daniel Black
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-24738 Improve the InnoDB deadlock checker Closed

 Description   

The deadlock section in SHOW ENGINE INNODB STATUS is always showing transaction 0 as being rolled back:

*** WE ROLL BACK TRANSACTION (0)

How to reproduce:

Use MariaDB 10.8 and generate a deadlock, then check SHOW ENGINE INNODB STATUS\G in the LATEST DETECTED DEADLOCK section.

mariadb session1> create table t1 (id int primary key, f1 int);
 
mariadb session1> insert into t1 values (1,1), (2,2);
 
mariadb session1> begin;
 
mariadb session1> update t1 set f1 = 3 where id = 1;
 
 
 
mariadb session2> begin;
 
mariadb session2> update t1 set f1 = 4 where id = 2;
 
 
 
mariadb session1> update t1 set f1 = 3 where id = 2;
 
 
 
mariadb session2> update t1 set f1 = 5 where id = 1;

– deadlock will be detected here. Check with:

mariadb> show engine innodb status\G
 
 
 
------------------------
 
LATEST DETECTED DEADLOCK
 
------------------------
 
2022-07-28 02:21:20 0x7f1ab00f9700
 
*** (1) TRANSACTION:
 
TRANSACTION 54, ACTIVE 15 sec starting index read
 
mysql tables in use 1, locked 1
 
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
 
MariaDB thread id 12, OS thread handle 139752599688960, query id 105 localhost root Updating
 
update t1 set f1 = 5 where id = 1
 
*** WAITING FOR THIS LOCK TO BE GRANTED:
 
RECORD LOCKS space id 6 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 54 lock_mode X locks rec but not gap waiting
 
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 
 0: len 4; hex 80000001; asc     ;;
 
 1: len 6; hex 000000000035; asc      5;;
 
 2: len 7; hex 16000001480110; asc     H  ;;
 
 3: len 4; hex 80000003; asc     ;;
 
 
 
*** CONFLICTING WITH:
 
RECORD LOCKS space id 6 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 53 lock_mode X locks rec but not gap
 
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 
 0: len 4; hex 80000001; asc     ;;
 
 1: len 6; hex 000000000035; asc      5;;
 
 2: len 7; hex 16000001480110; asc     H  ;;
 
 3: len 4; hex 80000003; asc     ;;
 
 
 
 
 
*** (2) TRANSACTION:
 
TRANSACTION 53, ACTIVE 46 sec starting index read
 
mysql tables in use 1, locked 1
 
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
 
MariaDB thread id 13, OS thread handle 139752600917760, query id 104 localhost root Updating
 
update t1 set f1 = 3 where id = 2
 
*** WAITING FOR THIS LOCK TO BE GRANTED:
 
RECORD LOCKS space id 6 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 53 lock_mode X locks rec but not gap waiting
 
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 
 0: len 4; hex 80000002; asc     ;;
 
 1: len 6; hex 000000000036; asc      6;;
 
 2: len 7; hex 17000001490110; asc     I  ;;
 
 3: len 4; hex 80000004; asc     ;;
 
 
 
*** CONFLICTING WITH:
 
RECORD LOCKS space id 6 page no 3 n bits 8 index PRIMARY of table `test`.`t1` trx id 54 lock_mode X locks rec but not gap
 
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 
 0: len 4; hex 80000002; asc     ;;
 
 1: len 6; hex 000000000036; asc      6;;
 
 2: len 7; hex 17000001490110; asc     I  ;;
 
 3: len 4; hex 80000004; asc     ;;
 
 
 
*** WE ROLL BACK TRANSACTION (0)

As we can see there, there is no TRANSACTION listed with ID 0 in there.
This is the same if we generate a deadlock involving three transactions:

------------------------
 
LATEST DETECTED DEADLOCK
 
------------------------
 
2022-07-28 01:44:51 0x7f1ab018f700
 
*** (1) TRANSACTION:
 
TRANSACTION 36, ACTIVE 185 sec starting index read
 
...
 
*** (2) TRANSACTION:
 
TRANSACTION 37, ACTIVE 171 sec starting index read
 
...
 
*** (3) TRANSACTION:
 
TRANSACTION 38, ACTIVE 160 sec starting index read
 
 
 
*** WE ROLL BACK TRANSACTION (0)

Let me know if there is anything else I should provide here.

shell> mysql
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 15
 
Server version: 10.8.3-MariaDB-log MariaDB Server
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

Thanks!

 Comments   
Comment by Marko Mäkelä [ 2022-07-28 ]

The deadlock detector was rewritten in MDEV-24738. The number is not a transaction identifier, but a position in the output.

Before that rewrite, the deadlock detector would always display (1) or (2) and report only 2 transactions, which would be very confusing if a deadlock involves more than 2 transactions.

Comment by Marko Mäkelä [ 2022-07-28 ]

It looks like the position is off by one; the involved transactions are listed as starting from (1).

Comment by Marko Mäkelä [ 2022-07-28 ]

danblack, thank you for analyzing and fixing this. The position would actually always be reported as (0), because I forgot to increment the counter.

Comment by Daniel Black [ 2022-07-28 ]

Thanks guliandro for the bug report and test cases. This will be fixed in the next release (sometime in the next week).

Comment by Agustin [ 2022-07-28 ]

Hi Marko and Daniel,

First, thanks both for the fast turnaround on this! Really amazing.

Regarding:
>The number is not a transaction identifier, but a position in the output.

Indeed, sorry for not being clear enough on this.

Thanks again!
Agustín.

Generated at Thu Feb 08 10:06:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.