diff --git a/mysql-test/suite/innodb/r/autoinc_debug.result b/mysql-test/suite/innodb/r/autoinc_debug.result index 585dafeec9d5b..0b80a69c9dd6e 100644 --- a/mysql-test/suite/innodb/r/autoinc_debug.result +++ b/mysql-test/suite/innodb/r/autoinc_debug.result @@ -108,6 +108,8 @@ SET DEBUG_SYNC='RESET'; # # MDEV-33593: Auto increment deadlock error causes ASSERT in subsequent save point # +SET @saved_print_all_deadlocks = @@GLOBAL.innodb_print_all_deadlocks; +SET GLOBAL innodb_print_all_deadlocks = ON; CREATE TABLE t1(col1 INT PRIMARY KEY AUTO_INCREMENT, col2 INT) ENGINE=InnoDB; CREATE TABLE t2(col1 INT PRIMARY KEY) ENGINE=InnoDB; INSERT INTO t1(col2) values(100); @@ -133,6 +135,37 @@ SET DEBUG_SYNC='now WAIT_FOR t3_waiting'; SET debug_dbug = '+d,innodb_deadlock_victim_self'; INSERT INTO t1(col2) VALUES(200); ERROR HY000: Failed to read auto-increment value from storage engine +# Verify deadlock info is available in session warnings (MDEV-34686) +SHOW WARNINGS; +Level Code Message +Note 1213 TIMESTAMP 0xTHD +*** (1) TRANSACTION: +TRANSACTION TRX_ID, ACTIVE N sec inserting +mysql tables in use 2, locked 2 +LOCK WAIT N lock struct(s), heap size N, N row lock(s) +MariaDB thread id TID, OS thread handle TID, query id QID localhost root Sending data +INSERT INTO t1(col2) SELECT col2 from t1 +*** WAITING FOR THIS LOCK TO BE GRANTED: +RECORD LOCKS space id ID page no N n bits N index PRIMARY of table `test`.`t1` trx id TRX_ID lock_mode X insert intention waiting +Record lock, heap no 1 PHYSICAL RECORD: n_fields N; compact format; info bits N + 0: len 8; hex HEX; asc DATA;; + + +*** (3) TRANSACTION: +TRANSACTION TRX_ID, ACTIVE N sec setting auto-inc lock +mysql tables in use 1, locked 1 +LOCK WAIT N lock struct(s), heap size N, N row lock(s), undo log entries N +MariaDB thread id TID, OS thread handle TID, query id QID localhost root Update +INSERT INTO t1(col2) VALUES(200) +*** WAITING FOR THIS LOCK TO BE GRANTED: +TABLE LOCK table `test`.`t1` trx id TRX_ID lock mode AUTO-INC waiting +*** CONFLICTING WITH: +TABLE LOCK table `test`.`t1` trx id TRX_ID lock mode IX +TABLE LOCK table `test`.`t1` trx id TRX_ID lock mode IS +TABLE LOCK table `test`.`t1` trx id TRX_ID lock mode AUTO-INC +TABLE LOCK table `test`.`t1` trx id TRX_ID lock mode IX +*** WE ROLL BACK TRANSACTION (1) +Error 1467 Failed to read auto-increment value from storage engine # The transaction should have been rolled back SELECT * FROM t1; col1 col2 @@ -159,6 +192,7 @@ col1 100 DROP TABLE t2; SET DEBUG_SYNC='RESET'; +SET GLOBAL innodb_print_all_deadlocks = @saved_print_all_deadlocks; # # End of 10.5 tests # diff --git a/mysql-test/suite/innodb/t/autoinc_debug.test b/mysql-test/suite/innodb/t/autoinc_debug.test index f62cfd8afce09..5d40686b6b9e8 100644 --- a/mysql-test/suite/innodb/t/autoinc_debug.test +++ b/mysql-test/suite/innodb/t/autoinc_debug.test @@ -5,6 +5,7 @@ --disable_query_log call mtr.add_suppression("InnoDB: Transaction was aborted due to "); +call mtr.add_suppression("Transactions deadlock detected"); --enable_query_log # Two parallel connection with autoinc column after restart. @@ -101,6 +102,9 @@ SET DEBUG_SYNC='RESET'; --echo # MDEV-33593: Auto increment deadlock error causes ASSERT in subsequent save point --echo # +SET @saved_print_all_deadlocks = @@GLOBAL.innodb_print_all_deadlocks; +SET GLOBAL innodb_print_all_deadlocks = ON; + CREATE TABLE t1(col1 INT PRIMARY KEY AUTO_INCREMENT, col2 INT) ENGINE=InnoDB; CREATE TABLE t2(col1 INT PRIMARY KEY) ENGINE=InnoDB; INSERT INTO t1(col2) values(100); @@ -131,6 +135,10 @@ SET debug_dbug = '+d,innodb_deadlock_victim_self'; --error ER_AUTOINC_READ_FAILED INSERT INTO t1(col2) VALUES(200); +--echo # Verify deadlock info is available in session warnings (MDEV-34686) +--replace_regex /[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}/TIMESTAMP/ /0x[0-9a-f]+/0xTHD/ /OS thread handle [0-9]+/OS thread handle TID/ /::1 // /127\.0\.0\.1 // /localhost::[0-9]* // /thread id [0-9]+/thread id TID/ /query id [0-9]+/query id QID/ /trx id [0-9]+/trx id TRX_ID/ /TRANSACTION [0-9]+/TRANSACTION TRX_ID/ /space id [0-9]+/space id ID/ /page no [0-9]+/page no N/ /n bits [0-9]+/n bits N/ /n_fields [0-9]+/n_fields N/ /info bits [0-9]+/info bits N/ /ACTIVE [0-9]+ sec/ACTIVE N sec/ /heap size [0-9]+/heap size N/ /[0-9]+ lock struct\(s\)/N lock struct(s)/ /[0-9]+ row lock\(s\)/N row lock(s)/ /undo log entries [0-9]+/undo log entries N/ /hex [0-9a-f]+; asc .*;;/hex HEX; asc DATA;;/ +SHOW WARNINGS; + --echo # The transaction should have been rolled back SELECT * FROM t1; SELECT * FROM t2; @@ -158,6 +166,7 @@ SELECT * FROM t2; DROP TABLE t2; SET DEBUG_SYNC='RESET'; +SET GLOBAL innodb_print_all_deadlocks = @saved_print_all_deadlocks; --echo # --echo # End of 10.5 tests diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc index 91af7afe14530..6356ad54acdb4 100644 --- a/storage/innobase/lock/lock0lock.cc +++ b/storage/innobase/lock/lock0lock.cc @@ -7182,6 +7182,7 @@ and less modified rows. Bit 0 is used to prefer orig_trx in case of a tie. static const char rollback_msg[]= "*** WE ROLL BACK TRANSACTION (%u)\n"; char buf[9 + sizeof rollback_msg]; trx_t *victim= nullptr; + char *deadlock_info= nullptr; /* Here, lock elision does not make sense, because for the output we are going to invoke system calls, @@ -7309,16 +7310,38 @@ and less modified rows. Bit 0 is used to prefer orig_trx in case of a tie. DBUG_EXECUTE_IF("innodb_deadlock_victim_self", victim= trx;); ut_ad(victim->state == TRX_STATE_ACTIVE); - /* victim->lock.was_chosen_as_deadlock_victim must always be set before - releasing waiting locks and resetting trx->lock.wait_lock */ victim->lock.was_chosen_as_deadlock_victim= true; DEBUG_SYNC_C("deadlock_report_before_lock_releasing"); lock_cancel_waiting_and_release(victim->lock.wait_lock); + + if (!srv_print_all_deadlocks) + goto func_exit; + long len= ftell(lock_latest_err_file); + if (len <= 0) + goto func_exit; + deadlock_info= static_cast(ut_malloc_nokey( + static_cast(len) + 1)); + if (!deadlock_info) + goto func_exit; + rewind(lock_latest_err_file); + size_t deadlock_info_len= fread(deadlock_info, 1, + static_cast(len), + lock_latest_err_file); + ut_ad(deadlock_info_len <= static_cast(len)); + if (deadlock_info[deadlock_info_len - 1] == '\n') + --deadlock_info_len; + deadlock_info[deadlock_info_len]= '\0'; } func_exit: if (current_trx) lock_sys.wr_unlock(); + + if (deadlock_info && current_trx && victim == trx && trx->mysql_thd) + push_warning(trx->mysql_thd, Sql_condition::WARN_LEVEL_NOTE, + ER_LOCK_DEADLOCK, deadlock_info); + ut_free(deadlock_info); + return victim; } }