From 7d6cebb96fcedecfe20649aa7a97b23c3f02a85f Mon Sep 17 00:00:00 2001 From: Venkatesh Prasad Venugopal Date: Thu, 20 Aug 2020 15:02:32 +0530 Subject: [PATCH] Bug #100586 Assertion failure `m_status == DA_ERROR` in `Diagnostics_area::mysql_errno()` https://bugs.mysql.com/bug.php?id=100586 Background ---------- In general, if a replication applier thread fails to execute a transaction because of an InnoDB deadlock or because the transaction's execution time exceeded InnoDB's innodb_lock_wait_timeout, it automatically retries slave_transaction_retries times before stopping with an error. And when --slave_preserve_commit_order is enabled, the replica server ensures that transactions are externalized on the replica in the same order as they appear in the replica's relay log, and prevents gaps in the sequence of transactions that have been executed from the relay log. If a thread's execution is completed before its preceding thread, then the executing thread waits until all previous transactions are committed before committing. Problem & Analysis ------------------ When --slave_preserve_commit_order is enabled on slave and if the waiting thread has locked the rows which are needed by the thread executing the previous transaction(as per relay log), then the innodb deadlock detection algorithm detects the deadlock between workers and will ask the waiting thread to rollback (only if its sequence number is lesser than that of the waiting thread). When this happens, the waiting thread wakes up from the cond_wait(SPCO) and it gets to know that it was asked to rollback by its preceding transaction as it was holding a lock that is needed by the other transaction to progress. It then rolls back its transaction so that the the preceding transaction can be committed and retries the transaction. But just before the transaction is retried, the worker checks if it encountered any errors during its execution. If there is no error, it simulates ER_LOCK_DEADLOCK error in order for it to be considered as a temporary error so that the worker thread retries the transaction. However, when the retries are exhausted, the worker thread logs an error into the error log by accessing the thread's diagnostic_area by calling `thd->get_stmt_da()->mysql_errno()`. If the error had been simulate (not called through `my_error` function call), the diagnostic_area would still be empty and thus making the assertion `DBUG_ASSERT(m_status == DA_ERROR);` to fail. NOTE: This assertion is observed only when both slave_transaction_retries and slave_preserve_commit_order are enabled on the replica server and is more likely to happen when slave_transaction_retries is set to a lower value. Fix --- `Slave_transaction:::retry_transaction()` has been modified to call `thd->get_stmt_da()->mysql_errno()` only when `thd->is_error()` is evaluated to true. --- ...dlock_slave_trans_retries_assertion.result | 73 ++++++++ ...eadlock_slave_trans_retries_assertion.test | 157 ++++++++++++++++++ sql/rpl_rli_pdb.cc | 17 +- 3 files changed, 240 insertions(+), 7 deletions(-) create mode 100644 mysql-test/suite/rpl/r/rpl_mts_spco_deadlock_slave_trans_retries_assertion.result create mode 100644 mysql-test/suite/rpl/t/rpl_mts_spco_deadlock_slave_trans_retries_assertion.test diff --git a/mysql-test/suite/rpl/r/rpl_mts_spco_deadlock_slave_trans_retries_assertion.result b/mysql-test/suite/rpl/r/rpl_mts_spco_deadlock_slave_trans_retries_assertion.result new file mode 100644 index 00000000000..dc34171fec9 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_mts_spco_deadlock_slave_trans_retries_assertion.result @@ -0,0 +1,73 @@ +# +# 1. Create source-replica topolgy. +include/master-slave.inc +Warnings: +Note #### Sending passwords in plain text without SSL/TLS is extremely insecure. +Note #### Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information. +[connection master] +# +# 2. Setup testing environment. +# 2.1. Create table on source and insert few rows. +# 2.2. Setup necessary variables on replica server. +CREATE TABLE t1(c1 INT PRIMARY KEY, c2 INT, INDEX(c2)) ENGINE = InnoDB; +INSERT INTO t1 VALUES(1, NULL),(2, 2), (3, NULL), (4, 4), (5, NULL), (6, 6); +include/sync_slave_sql_with_master.inc +include/stop_slave_sql.inc +SET @saved_slave_parallel_type = @@GLOBAL.slave_parallel_type; +SET @saved_slave_parallel_workers = @@GLOBAL.slave_parallel_workers; +SET @saved_slave_preserve_commit_order = @@GLOBAL.slave_preserve_commit_order; +SET @saved_innodb_lock_wait_timeout = @@GLOBAL.innodb_lock_wait_timeout; +SET @saved_slave_transaction_retries = @@GLOBAL.slave_transaction_retries; +SET GLOBAL slave_transaction_retries = 2; +SET GLOBAL slave_parallel_type = "LOGICAL_CLOCK"; +SET GLOBAL slave_parallel_workers = 2; +SET GLOBAL slave_preserve_commit_order = ON; +SET GLOBAL innodb_lock_wait_timeout = 1000; +# +# 3. Execute transactions on source server that would generate deadlock on the +# replica server. +[connection master] +INSERT INTO t1 VALUES(10, 10); +# Adding debug point 'set_commit_parent_100' to @@GLOBAL.debug +INSERT INTO t1 VALUES(11, NULL); +DELETE FROM t1 WHERE c2 <= 3; +# Removing debug point 'set_commit_parent_100' from @@GLOBAL.debug +[connection slave] +BEGIN; +INSERT INTO t1 VALUES(11, 11); +[connection slave1] +include/start_slave_sql.inc +# +# 4. When the replica server finds the deadlock, it will rollback w2 in +# order to allow w1 to commit first. When w2 rolls back the transaction +# and retries it, simulate that all retries are exhausted so that it +# tries to log a message in the error log. +# Adding debug point 'simulate_exhausted_trans_retries' to @@GLOBAL.debug +[connection slave] +ROLLBACK; +# +# 5. Wait till the co-ordinator thread to error out with ER_LOCK_DEADLOCK. +include/wait_for_slave_sql_error.inc [errno=1213] +# Removing debug point 'simulate_exhausted_trans_retries' from @@GLOBAL.debug +include/start_slave_sql.inc +# +# 6. Restart replication threads, sync the replica and verify that table +# data is consistent. +[connection master] +include/sync_slave_sql_with_master.inc +include/rpl_diff.inc +# +# 7. Cleanup. +[connection slave] +include/stop_slave_sql.inc +SET GLOBAL slave_transaction_retries = @saved_slave_transaction_retries; +SET GLOBAL slave_parallel_type = @saved_slave_parallel_type; +SET GLOBAL slave_parallel_workers = @saved_slave_parallel_workers; +SET GLOBAL slave_preserve_commit_order = @saved_slave_preserve_commit_order; +SET GLOBAL innodb_lock_wait_timeout = @saved_innodb_lock_wait_timeout; +include/start_slave_sql.inc +CALL mtr.add_suppression("Consider raising the value of the slave_transaction_retries variable"); +CALL mtr.add_suppression("The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state."); +[connection master] +DROP TABLE t1; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_mts_spco_deadlock_slave_trans_retries_assertion.test b/mysql-test/suite/rpl/t/rpl_mts_spco_deadlock_slave_trans_retries_assertion.test new file mode 100644 index 00000000000..c1a71e0a552 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_mts_spco_deadlock_slave_trans_retries_assertion.test @@ -0,0 +1,157 @@ +# ==== Purpose ==== +# +# This test verifies that deadlock errors arising due to lock conflicts are +# handled properly when --slave-preserve-commit-order is enabled on the replica +# server. +# +# ==== Implementation ==== +# +# 1. Create source-replica topolgy. +# 2. Setup testing environment. +# 2.1. Create table on source and insert few rows. +# 2.2. Setup necessary variables on replica server. +# 3. Execute transactions on source server that would generate deadlock on the +# replica server. +# +# The commands used to generate deadlock in this test are: +# +# INSERT INTO t1 (11, NULL); +# DELETE FROM t1 WHERE c2 <= 3; +# +# With the help of debug points on the source server, simulate that they are +# executed parallely on master and make sure INSERT is binlogged before +# DELETE. +# +# On replica server, they are applied parallel by w1 and w2. And the deadlock is: +# w1 w2 +# ------------------------- -------------------------- +# Applying INSERT Applying DELETE +# Gets the row locks first. +# Waits for w2 to release +# the row lock. +# Waits for w1 to commit. +# +# For these two special statements, INSERT doesn't block DELETE, but DELETE +# does block the INSERT because of the gap locks. +# +# 4. When the replica server finds the deadlock, it will rollback w2 in order +# to allow w1 to commit first. When w2 rolls back the transaction and retries +# it, simulate that all retries are exhausted so that it tries to +# log a message in the error log. +# 5. Wait till the co-ordinator thread to error out with ER_LOCK_DEADLOCK. +# 6. Restart replication threads, sync the replica and verify that table data is +# consistent. +# 7. Cleanup. +# +# ==== References ==== +# +# Bug #100586 Assertion failure `m_status == DA_ERROR` in `Diagnostics_area::mysql_errno()` + +# The test needs debug binaries +--source include/have_debug.inc +--source include/have_binlog_format_statement.inc + +--echo # +--echo # 1. Create source-replica topolgy. +--source include/master-slave.inc + +--echo # +--echo # 2. Setup testing environment. +--echo # 2.1. Create table on source and insert few rows. +--echo # 2.2. Setup necessary variables on replica server. + +CREATE TABLE t1(c1 INT PRIMARY KEY, c2 INT, INDEX(c2)) ENGINE = InnoDB; +INSERT INTO t1 VALUES(1, NULL),(2, 2), (3, NULL), (4, 4), (5, NULL), (6, 6); + +--source include/sync_slave_sql_with_master.inc +--source include/stop_slave_sql.inc +SET @saved_slave_parallel_type = @@GLOBAL.slave_parallel_type; +SET @saved_slave_parallel_workers = @@GLOBAL.slave_parallel_workers; +SET @saved_slave_preserve_commit_order = @@GLOBAL.slave_preserve_commit_order; +SET @saved_innodb_lock_wait_timeout = @@GLOBAL.innodb_lock_wait_timeout; +SET @saved_slave_transaction_retries = @@GLOBAL.slave_transaction_retries; + +SET GLOBAL slave_transaction_retries = 2; +SET GLOBAL slave_parallel_type = "LOGICAL_CLOCK"; +SET GLOBAL slave_parallel_workers = 2; +SET GLOBAL slave_preserve_commit_order = ON; +# Set it to a long time to guarantee it doesn't report timeout error. +SET GLOBAL innodb_lock_wait_timeout = 1000; + +--echo # +--echo # 3. Execute transactions on source server that would generate deadlock on the +--echo # replica server. +--source include/rpl_connection_master.inc + +# There is a bug that the first two transactions cannot be applied parallel. +# So we need to an extra transaction here. +INSERT INTO t1 VALUES(10, 10); + +--let $debug_point= set_commit_parent_100 +--source include/add_debug_point.inc +INSERT INTO t1 VALUES(11, NULL); +DELETE FROM t1 WHERE c2 <= 3; +--source include/remove_debug_point.inc + +# Start a local transaction on replica to block the INSERT statement coming +# through the replication channel. +--source include/rpl_connection_slave.inc +BEGIN; +INSERT INTO t1 VALUES(11, 11); + +# Wait till DELETE statement(w2) waits for the the preceding transaction(w1) to commit. +--source include/rpl_connection_slave1.inc +--source include/start_slave_sql.inc +--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for preceding transaction to commit" +--source include/wait_condition.inc + +--echo # +--echo # 4. When the replica server finds the deadlock, it will rollback w2 in +--echo # order to allow w1 to commit first. When w2 rolls back the transaction +--echo # and retries it, simulate that all retries are exhausted so that it +--echo # tries to log a message in the error log. + +--let $debug_point = simulate_exhausted_trans_retries +--source include/add_debug_point.inc + +# Resume the INSERT statement and trigger the deadlock +--source include/rpl_connection_slave.inc +ROLLBACK; + +--echo # +--echo # 5. Wait till the co-ordinator thread to error out with ER_LOCK_DEADLOCK. +--let $slave_sql_errno = convert_error(ER_LOCK_DEADLOCK) +--source include/wait_for_slave_sql_error.inc + +# Remove the debug point +--source include/remove_debug_point.inc +--source include/start_slave_sql.inc + +--echo # +--echo # 6. Restart replication threads, sync the replica and verify that table +--echo # data is consistent. +--source include/rpl_connection_master.inc +--source include/sync_slave_sql_with_master.inc + +--let $rpl_diff_statement= SELECT * FROM t1; +--source include/rpl_diff.inc + +--echo # +--echo # 7. Cleanup. + +--source include/rpl_connection_slave.inc +--source include/stop_slave_sql.inc +SET GLOBAL slave_transaction_retries = @saved_slave_transaction_retries; +SET GLOBAL slave_parallel_type = @saved_slave_parallel_type; +SET GLOBAL slave_parallel_workers = @saved_slave_parallel_workers; +SET GLOBAL slave_preserve_commit_order = @saved_slave_preserve_commit_order; +SET GLOBAL innodb_lock_wait_timeout = @saved_innodb_lock_wait_timeout; +--source include/start_slave_sql.inc + +# Add suppressions on replica server. +CALL mtr.add_suppression("Consider raising the value of the slave_transaction_retries variable"); +CALL mtr.add_suppression("The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state."); + +--source include/rpl_connection_master.inc +DROP TABLE t1; +--source include/rpl_end.inc diff --git a/sql/rpl_rli_pdb.cc b/sql/rpl_rli_pdb.cc index 9fd746f788c..964b29d5910 100644 --- a/sql/rpl_rli_pdb.cc +++ b/sql/rpl_rli_pdb.cc @@ -1961,12 +1961,13 @@ bool Slave_worker::retry_transaction(uint start_relay_number, no error or the error is a temporary error. */ Diagnostics_area *da= thd->get_stmt_da(); - if (!thd->get_stmt_da()->is_error() || - has_temporary_error(thd, - da->is_error() ? da->mysql_errno() : error, + if (!da->is_error() || + has_temporary_error(thd, da->is_error() ? da->mysql_errno() : error, &silent)) { error= ER_LOCK_DEADLOCK; + DBUG_EXECUTE_IF("simulate_exhausted_trans_retries", + { trans_retries = slave_trans_retries; };); } #ifndef DBUG_OFF else @@ -1990,10 +1991,12 @@ bool Slave_worker::retry_transaction(uint start_relay_number, if (trans_retries >= slave_trans_retries) { thd->is_fatal_error= 1; - c_rli->report(ERROR_LEVEL, thd->get_stmt_da()->mysql_errno(), - "worker thread retried transaction %lu time(s) " - "in vain, giving up. Consider raising the value of " - "the slave_transaction_retries variable.", trans_retries); + c_rli->report( + ERROR_LEVEL, + thd->is_error() ? thd->get_stmt_da()->mysql_errno() : error, + "worker thread retried transaction %lu time(s) " + "in vain, giving up. Consider raising the value of " + "the slave_transaction_retries variable.", trans_retries); DBUG_RETURN(true); }