Bug #110584 add missing timestamp and headers information innodb_print_all_deadlocks

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;;

suggested add  patch

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: deadlock.patch (application/octet-stream, text), 1.29 KiB.

Hello bin wang,

Thank you for the report and contribution.

regards,
Umesh