Description:
if we set innodb_print_all_deadlocks value is ON and the default value for log_error_verbosity is 2. , we will have (partial) message in error.log:
TRANSACTION 6489, ACTIVE 14 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 22, OS thread handle 140499320264448, query id 218 localhost root statistics
select * from t where id = 2 for update
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 6489 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 00000000194a; asc J;;
2: len 7; hex 820000008c0110; asc ;;
3: len 1; hex 6a; asc j;;
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 6489 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 00000000194a; asc J;;
2: len 7; hex 820000008c011d; asc ;;
3: len 1; hex 6b; asc k;;
TRANSACTION 6490, ACTIVE 10 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 23, OS thread handle 140499723683584, query id 219 localhost root statistics
select * from t where id = 1 for update
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 6490 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 00000000194a; asc J;;
2: len 7; hex 820000008c011d; asc ;;
3: len 1; hex 6b; asc k;;
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 6490 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 00000000194a; asc J;;
2: len 7; hex 820000008c0110; asc ;;
3: len 1; hex 6a; asc j;;
--------------------------------------------------------------------
is is to understand the outputs given in the errlogs, since they don't have date/timestamp and are missing the headers describing what each section is.
when using log_error_verbosity = 3:
2023-04-03T18:03:15.438719+08:00 0 [Note] [MY-012468] [InnoDB] Transactions deadlock detected, dumping detailed information.
2023-04-03T18:03:15.438799+08:00 0 [Note] [MY-012469] [InnoDB] *** (1) TRANSACTION:
TRANSACTION 8469, ACTIVE 20 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 9, OS thread handle 140573611591424, query id 40 localhost root statistics
select * from t where id = 2 for update
2023-04-03T18:03:15.438834+08:00 0 [Note] [MY-012469] [InnoDB] *** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 8469 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 00000000194a; asc J;;
2: len 7; hex 820000008c0110; asc ;;
3: len 1; hex 6a; asc j;;
2023-04-03T18:03:15.441865+08:00 0 [Note] [MY-012469] [InnoDB] *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 8469 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 00000000194a; asc J;;
2: len 7; hex 820000008c011d; asc ;;
3: len 1; hex 6b; asc k;;
2023-04-03T18:03:15.443425+08:00 0 [Note] [MY-012469] [InnoDB] *** (2) TRANSACTION:
TRANSACTION 8470, ACTIVE 14 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 8, OS thread handle 140573612648192, query id 41 localhost root statistics
select * from t where id = 1 for update
2023-04-03T18:03:15.443644+08:00 0 [Note] [MY-012469] [InnoDB] *** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 8470 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 00000000194a; asc J;;
2: len 7; hex 820000008c011d; asc ;;
3: len 1; hex 6b; asc k;;
2023-04-03T18:03:15.445254+08:00 0 [Note] [MY-012469] [InnoDB] *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 12 page no 4 n bits 72 index PRIMARY of table `v`.`t` trx id 8470 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 00000000194a; asc J;;
2: len 7; hex 820000008c0110; asc ;;
3: len 1; hex 6a; asc j;;
2023-04-03T18:03:15.448164+08:00 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 `t` (
`id` int(11) NOT NULL,
`name` varchar(10) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB ;
insert into t1 values (1,"a"), (2,"b");
begin;
select * from t where id = 1 for update;
### Session 2:
use test;
begin;
select * from t where id = 2 for update;
### Session 1:
select * from t where id = 2 for update;
### Session 2:
select * from t where id = 1 for update;
the error log will have the deadlock messages printed.
Suggested fix:
innodb_print_all_deadlocks print deadlock mesage should not depend on other variables. Whenever innodb_print_all_deadlocks is ON or OFF , it should print all needed outputs, disregarding whatever log_error_verbosity default value .
suggest add
@@ -6318,6 +6318,15 @@
ut_print_timestamp(lock_latest_err_file);
if (srv_print_all_deadlocks) {
+ if(log_error_verbosity <3)
+ {
+ ut::ostringstream buff;
+ ut_print_timestamp(stderr);
+ buff << " *** Transactions deadlock detected, dumping"
+ << " detailed information.\n";
+ fputs(buff.str().c_str(), stderr);
+ return;
+ }
}
@@ -6394,6 +6403,15 @@
ut_ad(locksys::owns_exclusive_global_latch());
ut::ostringstream buff;
buff << "\n*** (" << (pos_on_cycle + 1) << ") " << title << ":\n";
+ if( log_error_verbosity <3)
+ {
+ ut::ostringstream buff_title;
+ buff_title << " *** " << title << ":";
+ ut_print_timestamp(stderr);
+ fputs(buff_title.str().c_str(), stderr);
+ putc('\n', stderr);
+ return;
+ }
print(buff.str().c_str());
}
after add the deadlock output is following,whatever log_error_verbosity's value is.
2023-04-03 18:42:17 140294435628800 *** Transactions deadlock detected, dumping detailed information.
2023-04-03 18:42:17 140294435628800 *** TRANSACTION:
TRANSACTION 9018, ACTIVE 17 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 12, OS thread handle 140295712069376, query id 72 localhost root statistics
select * from t where id = 2 for update
2023-04-03 18:42:17 140294435628800 *** HOLDS THE LOCK(S):
RECORD LOCKS space id 14 page no 4 n bits 72 index PRIMARY of table `test`.`t` trx id 9018 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 000000002333; asc #3;;
2: len 7; hex 82000000860110; asc ;;
3: len 1; hex 61; asc a;;
2023-04-03 18:42:17 140294435628800 *** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 14 page no 4 n bits 72 index PRIMARY of table `test`.`t` trx id 9018 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 000000002333; asc #3;;
2: len 7; hex 8200000086011d; asc ;;
3: len 1; hex 62; asc b;;
2023-04-03 18:42:17 140294435628800 *** TRANSACTION:
TRANSACTION 9019, ACTIVE 11 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 13, OS thread handle 140295310374656, query id 73 localhost root statistics
select * from t where id = 1 for update
2023-04-03 18:42:17 140294435628800 *** HOLDS THE LOCK(S):
RECORD LOCKS space id 14 page no 4 n bits 72 index PRIMARY of table `test`.`t` trx id 9019 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 000000002333; asc #3;;
2: len 7; hex 8200000086011d; asc ;;
3: len 1; hex 62; asc b;;
2023-04-03 18:42:17 140294435628800 *** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 14 page no 4 n bits 72 index PRIMARY of table `test`.`t` trx id 9019 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 000000002333; asc #3;;
2: len 7; hex 82000000860110; asc ;;
3: len 1; hex 61; asc a;;