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.
