revision-id: 256008295932c655aed7ed7b466b9409c45ce2e5 (mariadb-10.1.33-31-g25600829593) parent(s): 3b7da8a44c8a0ff4b40b37e4db01f7e397aefab5 author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-06-06 13:41:13 +0300 message: MDEV-13577 slave_parallel_mode=optimistic should not report the mode's specific temporary errors The optimistic parallel slave's worker thread could face a run-time error due to the algorithm's specifics which allows for conflicts like the reported "Can't find record in 'table'". A typical stack is like {noformat} #0 handler::print_error (this=0x61c00008f8a0, error=149, errflag=0) at handler.cc:3650 #1 0x0000555555e95361 in write_record (thd=thd@entry=0x62a0000a2208, table=table@entry=0x61f00008ce88, info=info@entry=0x7fffdee356d0) at sql_insert.cc:1944 #2 0x0000555555ea7767 in mysql_insert (thd=thd@entry=0x62a0000a2208, table_list=0x61b00012ada0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=<optimized out>, ignore=<optimized out>) at sql_insert.cc:1039 #3 0x0000555555efda90 in mysql_execute_command (thd=thd@entry=0x62a0000a2208) at sql_parse.cc:3927 #4 0x0000555555f0cc50 in mysql_parse (thd=0x62a0000a2208, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at sql_parse.cc:7449 #5 0x00005555566d4444 in Query_log_event::do_apply_event (this=0x61200005b9c8, rgi=<optimized out>, query_arg=<optimized out>, q_len_arg=<optimized out>) at log_event.cc:4508 #6 0x00005555566d639e in Query_log_event::do_apply_event (this=<optimized out>, rgi=<optimized out>) at log_event.cc:4185 #7 0x0000555555d738cf in Log_event::apply_event (rgi=0x61d0001ea080, this=0x61200005b9c8) at log_event.h:1343 #8 apply_event_and_update_pos_apply (ev=ev@entry=0x61200005b9c8, thd=thd@entry=0x62a0000a2208, rgi=rgi@entry=0x61d0001ea080, reason=<optimized out>) at slave.cc:3479 #9 0x0000555555d8596b in apply_event_and_update_pos_for_parallel (ev=ev@entry=0x61200005b9c8, thd=thd@entry=0x62a0000a2208, rgi=rgi@entry=0x61d0001ea080) at slave.cc:3623 #10 0x00005555562aca83 in rpt_handle_event (qev=qev@entry=0x6190000fa088, rpt=rpt@entry=0x62200002bd68) at rpl_parallel.cc:50 #11 0x00005555562bd04e in handle_rpl_parallel_thread (arg=arg@entry=0x62200002bd68) at rpl_parallel.cc:1258 {noformat} Here {{handler::print_error}} computes whether to error log the current error when --log-warnings=2 inside {{my_message_sql()}} which can be eventually called. In the bug case the decision is to log. However in the optimistic mode slave applier case any conflict is attempted to resolve with rollback and retry to success. Hence the logging is at least extraneous. The case is fixed with refining my_message_sql() to downgrade optionally when --log-warnings=2 the formerly error level to the warning one when the error comes from the *optimistically* {{rpl_group_info::SPECULATE_OPTIMISTIC}} running parallel slave thread. In case of a specific to the optimistical mode ER_PRIOR_COMMIT_FAILED the parallel thread won't retry the error, but it remains to be reported properly with the error level through {{slave_output_error_info()}} as usual. --- .../extra/rpl_tests/rpl_init_debug_sync_func.inc | 39 +++++++++++++++ .../suite/rpl/r/rpl_parallel_optimistic.result | 46 ++++++++++++++++++ .../suite/rpl/t/rpl_parallel_optimistic.test | 56 ++++++++++++++++++++++ sql/mysqld.cc | 23 +++++++++ 4 files changed, 164 insertions(+) diff --git a/mysql-test/extra/rpl_tests/rpl_init_debug_sync_func.inc b/mysql-test/extra/rpl_tests/rpl_init_debug_sync_func.inc new file mode 100644 index 00000000000..5a3e84b9ea0 --- /dev/null +++ b/mysql-test/extra/rpl_tests/rpl_init_debug_sync_func.inc @@ -0,0 +1,39 @@ +# Define a stored function to inject a debug_sync into the appropriate +# slave worker THD. +# The function does nothing on the master, and on the +# slave it injects the desired debug_sync action(s). +# +# Slave must be running. server_1, server_2 connections are to the +# master and slave respectively. + +--connection server_1 +SET sql_log_bin=0; +--delimiter || +CREATE FUNCTION foo(x INT, d1 VARCHAR(500), d2 VARCHAR(500)) + RETURNS INT DETERMINISTIC + BEGIN + RETURN x; + END +|| +--delimiter ; +SET sql_log_bin=1; +--save_master_pos + +--connection server_2 +SET sql_log_bin=0; +--delimiter || +CREATE FUNCTION foo(x INT, d1 VARCHAR(500), d2 VARCHAR(500)) + RETURNS INT DETERMINISTIC + BEGIN + IF d1 != '' THEN + SET debug_sync = d1; + END IF; + IF d2 != '' THEN + SET debug_sync = d2; + END IF; + RETURN x; + END +|| +--delimiter ; +SET sql_log_bin=1; +--sync_with_master diff --git a/mysql-test/suite/rpl/r/rpl_parallel_optimistic.result b/mysql-test/suite/rpl/r/rpl_parallel_optimistic.result index 0177e65b10f..24926ebcf6a 100644 --- a/mysql-test/suite/rpl/r/rpl_parallel_optimistic.result +++ b/mysql-test/suite/rpl/r/rpl_parallel_optimistic.result @@ -543,6 +543,52 @@ a b 57 7 58 8 59 9 +DELETE FROM t1; +DELETE FROM t2; +include/save_master_gtid.inc +include/sync_with_master_gtid.inc +SET sql_log_bin=0; +CREATE FUNCTION foo(x INT, d1 VARCHAR(500), d2 VARCHAR(500)) +RETURNS INT DETERMINISTIC +BEGIN +RETURN x; +END +|| +SET sql_log_bin=1; +SET sql_log_bin=0; +CREATE FUNCTION foo(x INT, d1 VARCHAR(500), d2 VARCHAR(500)) +RETURNS INT DETERMINISTIC +BEGIN +IF d1 != '' THEN +SET debug_sync = d1; +END IF; +IF d2 != '' THEN +SET debug_sync = d2; +END IF; +RETURN x; +END +|| +SET sql_log_bin=1; +BEGIN; +INSERT INTO t2 SET a=1; +SET @save.binlog_format=@@session.binlog_format; +SET @@SESSION.binlog_format=statement; +BEGIN; +INSERT INTO t2 SET a=1; +INSERT INTO t1 SET a=1; +COMMIT; +SET @@SESSION.binlog_format=mixed; +BEGIN; +INSERT INTO t2 SET a=foo(100, 'rpl_parallel_retry_after_unmark WAIT_FOR go_retrying', ''); +DELETE FROM t1 WHERE a=sleep(0) + 1; +COMMIT; +ROLLBACK; +SET debug_sync='now SIGNAL go_retrying'; +SET @@SESSION.binlog_format= @save.binlog_format; +DROP FUNCTION foo; +include/save_master_gtid.inc +include/sync_with_master_gtid.inc +SET debug_sync='RESET'; include/stop_slave.inc SET GLOBAL slave_parallel_mode=@old_parallel_mode; SET GLOBAL slave_parallel_threads=@old_parallel_threads; diff --git a/mysql-test/suite/rpl/t/rpl_parallel_optimistic.test b/mysql-test/suite/rpl/t/rpl_parallel_optimistic.test index 41fb6ebb72e..555ed9b93ca 100644 --- a/mysql-test/suite/rpl/t/rpl_parallel_optimistic.test +++ b/mysql-test/suite/rpl/t/rpl_parallel_optimistic.test @@ -480,6 +480,62 @@ SELECT * FROM t2 WHERE a >= 40 ORDER BY a; SELECT * FROM t1 WHERE a >= 40 ORDER BY a; SELECT * FROM t2 WHERE a >= 40 ORDER BY a; +# partial cleanup to reuse the tables by following tests +--connection server_1 +DELETE FROM t1; +DELETE FROM t2; +--source include/save_master_gtid.inc + +--connection server_2 +--source include/sync_with_master_gtid.inc + +# +# MDEV-13577 optimistic parallel slave errors out to error log unnecessary +# +--source extra/rpl_tests/rpl_init_debug_sync_func.inc + +# The 1st of the following two trx blocker on slave +--connection server_2 +BEGIN; +INSERT INTO t2 SET a=1; + +--connection server_1 +SET @save.binlog_format=@@session.binlog_format; +SET @@SESSION.binlog_format=statement; + +BEGIN; +INSERT INTO t2 SET a=1; +INSERT INTO t1 SET a=1; +COMMIT; + +# This transaction is going to win optimistical race with above INSERT +# on slave only to error out at the first attempt due to overly optimistic DELETE +# but to retry to succeed as specified. +SET @@SESSION.binlog_format=mixed; +BEGIN; + INSERT INTO t2 SET a=foo(100, 'rpl_parallel_retry_after_unmark WAIT_FOR go_retrying', ''); + DELETE FROM t1 WHERE a=sleep(0) + 1; +COMMIT; + +# First make sure DELETE raced indeed to get stuck: +--connection server_2 +--let $wait_condition= SELECT COUNT(*) > 0 FROM information_schema.processlist WHERE state = "debug sync point: rpl_parallel_retry_after_unmark" +--source include/wait_condition.inc + +# Next release the 1st trx to commit it and then release DELETE +--connection server_2 +ROLLBACK; +SET debug_sync='now SIGNAL go_retrying'; + +--connection server_1 +SET @@SESSION.binlog_format= @save.binlog_format; +DROP FUNCTION foo; +--source include/save_master_gtid.inc + +--connection server_2 +--source include/sync_with_master_gtid.inc +SET debug_sync='RESET'; + # Clean up. --connection server_2 diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 5f954f7576d..adcbc9bf11b 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -3487,6 +3487,28 @@ static void check_data_home(const char *path) #endif /*!EMBEDDED_LIBRARY*/ #endif /* __WIN__*/ +/** + Helper function for @c my_message_sql() to decide + how to errorlog for the slave thread worker + when it executes in the OPTIMISTIC parallel mode. A persistent + error by the slave worker does not escape being left out to + the driver thread to report. +*/ +inline void fix_func_for_slave_worker(THD *thd, + sql_print_message_func *ptr_func) +{ + DBUG_ASSERT(!(thd && thd->system_thread == SYSTEM_THREAD_SLAVE_SQL) || + thd->rgi_slave); + + if (thd && thd->system_thread == SYSTEM_THREAD_SLAVE_SQL && + thd->rgi_slave->speculation == rpl_group_info::SPECULATE_OPTIMISTIC) + { + if (global_system_variables.log_warnings > 1) + { + *ptr_func= sql_print_warning; + } + } +} /** All global error messages are sent here where the first one is stored @@ -3535,6 +3557,7 @@ void my_message_sql(uint error, const char *str, myf MyFlags) /* When simulating OOM, skip writing to error log to avoid mtr errors */ DBUG_EXECUTE_IF("simulate_out_of_memory", DBUG_VOID_RETURN;); + fix_func_for_slave_worker(thd, &func); if (!thd || thd->log_all_errors || (MyFlags & ME_NOREFRESH)) (*func)("%s: %s", my_progname_short, str); /* purecov: inspected */ DBUG_VOID_RETURN;