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/r/deadlock_report.result b/mysql-test/suite/innodb/r/deadlock_report.result new file mode 100644 index 0000000000000..27481f3fe8549 --- /dev/null +++ b/mysql-test/suite/innodb/r/deadlock_report.result @@ -0,0 +1,37 @@ +call mtr.add_suppression("InnoDB: Transaction was aborted due to "); +call mtr.add_suppression("Transactions deadlock detected"); +SET @save = @@GLOBAL.innodb_print_all_deadlocks; +SET GLOBAL innodb_print_all_deadlocks = ON; +CREATE TABLE t1 (id INT PRIMARY KEY) ENGINE=InnoDB; +CREATE TABLE t2 (a INT) ENGINE=InnoDB; +INSERT INTO t1 VALUES (1), (2); +INSERT INTO t2 VALUES (1),(2),(3),(4),(5),(6),(7),(8),(9),(10); +connect con1, localhost, root,,; +connect con2, localhost, root,,; +connection con2; +BEGIN; +UPDATE t2 SET a = a + 1; +SELECT * FROM t1 WHERE id = 2 FOR UPDATE; +id +2 +connection con1; +BEGIN; +SELECT * FROM t1 WHERE id = 1 FOR UPDATE; +id +1 +connection con2; +SELECT * FROM t1 WHERE id = 1 FOR UPDATE; +connection default; +connection con1; +SELECT * FROM t1 WHERE id = 2 FOR UPDATE; +ERROR 40001: Deadlock found when trying to get lock; try restarting transaction +connection con2; +id +1 +COMMIT; +disconnect con1; +disconnect con2; +connection default; +DROP TABLE t1, t2; +SET GLOBAL innodb_print_all_deadlocks = @save; +# 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/mysql-test/suite/innodb/t/deadlock_report.test b/mysql-test/suite/innodb/t/deadlock_report.test new file mode 100644 index 0000000000000..e2360c96724fc --- /dev/null +++ b/mysql-test/suite/innodb/t/deadlock_report.test @@ -0,0 +1,64 @@ +--source include/have_innodb.inc +--source include/not_embedded.inc + +# MDEV-34686: Deadlock info available in session warnings +# Verify deadlock info appears in SHOW WARNINGS when innodb_print_all_deadlocks=ON + +call mtr.add_suppression("InnoDB: Transaction was aborted due to "); +call mtr.add_suppression("Transactions deadlock detected"); + +SET @save = @@GLOBAL.innodb_print_all_deadlocks; +SET GLOBAL innodb_print_all_deadlocks = ON; + +CREATE TABLE t1 (id INT PRIMARY KEY) ENGINE=InnoDB; +# Table to increase transaction weight (locks + undo records) +CREATE TABLE t2 (a INT) ENGINE=InnoDB; +INSERT INTO t1 VALUES (1), (2); +INSERT INTO t2 VALUES (1),(2),(3),(4),(5),(6),(7),(8),(9),(10); + +--connect(con1, localhost, root,,) +--connect(con2, localhost, root,,) + +# con2: increase weight so con1 will be chosen as deadlock victim +--connection con2 +BEGIN; +UPDATE t2 SET a = a + 1; +SELECT * FROM t1 WHERE id = 2 FOR UPDATE; + +# con1: minimal weight +--connection con1 +BEGIN; +SELECT * FROM t1 WHERE id = 1 FOR UPDATE; + +# con2 waits for row 1 +--connection con2 +--send SELECT * FROM t1 WHERE id = 1 FOR UPDATE + +# Wait for con2 to enter lock wait +--connection default +let $wait_condition= + SELECT COUNT(*) >= 2 FROM information_schema.innodb_locks; +--source include/wait_condition.inc + +# con1 triggers deadlock - will be victim due to lower weight +--connection con1 +--error ER_LOCK_DEADLOCK +SELECT * FROM t1 WHERE id = 2 FOR UPDATE; + +# Deadlock info must appear as Note +--let $level = query_get_value(SHOW WARNINGS, Level, 1) +if (`SELECT '$level' != 'Note'`) { + --die First warning should be Note with deadlock info +} + +--connection con2 +--reap +COMMIT; + +--disconnect con1 +--disconnect con2 +--connection default +DROP TABLE t1, t2; +SET GLOBAL innodb_print_all_deadlocks = @save; + +--echo # End of 10.5 tests diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc index 91af7afe14530..440f36632fd3d 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,40 @@ 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 || !current_trx || victim != trx || + !trx->mysql_thd) + goto func_exit; + fflush(lock_latest_err_file); + 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_len && 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) + push_warning(trx->mysql_thd, Sql_condition::WARN_LEVEL_NOTE, + ER_LOCK_DEADLOCK, deadlock_info); + ut_free(deadlock_info); + return victim; } }