Bug #108891 innodb_print_all_deadlocks missing information.
Submitted: 26 Oct 2022 20:22 Modified: 27 Oct 2022 6:07
Reporter: Agustín G Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[26 Oct 2022 20:22] Agustín G
Description:
Since 8.0.4, the default value for log_error_verbosity has changed to 2. This means that if we enable innodb_print_all_deadlocks, we will have (partial) outputs like the following:

###########################################################
2022-10-26T18:47:42.179392Z 0 [System] [MY-010931] [Server] /opt/mysql/8.0.11/bin/mysqld: ready for connections. Version: '8.0.11'  socket: '/tmp/mysql_sandbox28011.sock'  port: 28011  MySQL Community Server - GPL.
TRANSACTION 1596, ACTIVE 12 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 140078698194688, query id 59 localhost msandbox updating
update t1 set f1=5 where id = 2
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 1596 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 00000000063d; asc      =;;
 2: len 7; hex 01000001170110; asc        ;;
 3: len 4; hex 80000003; asc     ;;

TRANSACTION 1597, ACTIVE 7 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 10, OS thread handle 140078681437952, query id 60 localhost msandbox updating
update t1 set f1=5 where id = 1
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 1597 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 00000000063d; asc      =;;
 2: len 7; hex 01000001170110; asc        ;;
 3: len 4; hex 80000003; asc     ;;

RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 1597 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 00000000063c; asc      <;;
 2: len 7; hex 02000001170110; asc        ;;
 3: len 4; hex 80000003; asc     ;;

###########################################################

This makes it hard (or impossible, even) to interpret the outputs given in the logs, since they don't have date/timestamp and are missing the headers describing what each section is. 

Compare the output while using log_error_verbosity = 3:

###########################################################
2022-10-26T20:08:00.299947Z 0 [System] [MY-010931] [Server] /opt/mysql/minimal/8.0.31/bin/mysqld: ready for connections. Version: '8.0.31'  socket: '/tmp/mysql_sandbox23877.sock'  port: 23877  MySQL Community Server - GPL.
2022-10-26T20:09:12.970684Z 0 [Note] [MY-012468] [InnoDB] Transactions deadlock detected, dumping detailed information.
2022-10-26T20:09:12.970747Z 0 [Note] [MY-012469] [InnoDB]  *** (1) TRANSACTION:
TRANSACTION 2326, ACTIVE 13 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
MySQL thread id 11, OS thread handle 140705079969536, query id 55 localhost msandbox updating
update t1 set f1=5 where id = 2
2022-10-26T20:09:12.970815Z 0 [Note] [MY-012469] [InnoDB]  *** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 2326 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 000000000916; asc       ;;
 2: len 7; hex 020000011703e0; asc        ;;
 3: len 4; hex 80000003; asc     ;;

2022-10-26T20:09:12.971025Z 0 [Note] [MY-012469] [InnoDB]  *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 2326 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 000000000917; asc       ;;
 2: len 7; hex 010000011f03aa; asc        ;;
 3: len 4; hex 80000003; asc     ;;

2022-10-26T20:09:12.971218Z 0 [Note] [MY-012469] [InnoDB]  *** (2) TRANSACTION:
TRANSACTION 2327, ACTIVE 6 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
MySQL thread id 12, OS thread handle 140705077856000, query id 56 localhost msandbox updating
update t1 set f1=5 where id = 1
2022-10-26T20:09:12.971260Z 0 [Note] [MY-012469] [InnoDB]  *** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 2327 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 000000000917; asc       ;;
 2: len 7; hex 010000011f03aa; asc        ;;
 3: len 4; hex 80000003; asc     ;;

2022-10-26T20:09:12.971427Z 0 [Note] [MY-012469] [InnoDB]  *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2 page no 4 n bits 72 index PRIMARY of table `test`.`t1` trx id 2327 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 000000000916; asc       ;;
 2: len 7; hex 020000011703e0; asc        ;;
 3: len 4; hex 80000003; asc     ;;

2022-10-26T20:09:12.971582Z 0 [Note] [MY-012469] [InnoDB] *** WE ROLL BACK TRANSACTION (2)
###########################################################

How to repeat:
Enable innodb_print_all_deadlocks in latest 8.0 and force a deadlock. To get full outputs with timestamps, repeat the tests while using log_error_verbosity=3.

### Session 1:
set global innodb_print_all_deadlocks = 1;
create schema test;
use test;
create table t1 (id int primary key, f1 int);
insert into t1 values (1,1), (2,2);
begin;
update t1 set f1=3 where id = 1;

### Session 2:
use test;
begin;
update t1 set f1=4 where id = 2;

### Session 1:
update t1 set f1=5 where id = 2;

### Session 2:
update t1 set f1=6 where id = 1;

At this point, the error log will have the messages printed.

Suggested fix:
innodb_print_all_deadlocks outputs' completeness shouldn't depend on other variables. Whenever innodb_print_all_deadlocks is enabled, it should print all needed outputs, disregarding what log_error_verbosity's value is.
[27 Oct 2022 6:07] MySQL Verification Team
Hello Agustín G,

Thank you for the report and feedback.

regards,
Umesh