From bc2c16a8870518548d8fd74bb089b318a2fc505c Mon Sep 17 00:00:00 2001 From: Abhinav Sharma Date: Mon, 31 Oct 2022 09:56:38 -0700 Subject: [PATCH] Adding a flag to delay auto binlog rotation when a raft purge is active Summary: Purging logs in raft is very expensive because we read logs to find the last opid for every to-be-purged binlog. Ideally we should be storing this info in the index file like the prev gtid set but that is a big work item. Purge can cause stalls in the commit pipeline when auto rotation is triggered (current binlog goes beyond max_binlog_size). To quick fix added an atomic to indicate if a raft purge is active, if yes, we delay to auto rotate operation in group commit, avoiding stalls at the cost of slighly exceeding max_binlog_size. Reviewed By: anirbanr-fb Differential Revision: D40743288 fbshipit-source-id: f51a6541f6d92d624d7c8f80d2caf586d1de6884 --------------------------------------------------------------------- Fix purge log duration logging Summary: Incorrect type %f was used in the format string Reviewed By: li-chi Differential Revision: D42725127 fbshipit-source-id: abd2ecc2fabb4bc8ca474c6a4ffdb4673d8bf0c0 --- mysql-test/r/mysqld--help-notwin.result | 6 +++ ...ft_delay_rotation_on_raft_log_purge.result | 52 +++++++++++++++++++ ...raft_delay_rotation_on_raft_log_purge.test | 43 +++++++++++++++ ...to_rotation_on_raft_log_purge_basic.result | 20 +++++++ ...auto_rotation_on_raft_log_purge_basic.test | 27 ++++++++++ sql/binlog.cc | 36 +++++++++++-- sql/binlog.h | 2 + sql/mysqld.cc | 1 + sql/mysqld.h | 1 + sql/sys_vars.cc | 8 +++ 10 files changed, 192 insertions(+), 4 deletions(-) create mode 100644 mysql-test/suite/rpl_raft/r/rpl_raft_delay_rotation_on_raft_log_purge.result create mode 100644 mysql-test/suite/rpl_raft/t/rpl_raft_delay_rotation_on_raft_log_purge.test create mode 100644 mysql-test/suite/sys_vars/r/delay_auto_rotation_on_raft_log_purge_basic.result create mode 100644 mysql-test/suite/sys_vars/t/delay_auto_rotation_on_raft_log_purge_basic.test diff --git a/mysql-test/r/mysqld--help-notwin.result b/mysql-test/r/mysqld--help-notwin.result index f2ce324fdad8..5174e40f6832 100644 --- a/mysql-test/r/mysqld--help-notwin.result +++ b/mysql-test/r/mysqld--help-notwin.result @@ -393,6 +393,11 @@ The following options may be given as the first argument: tables --default-week-format=# The default week format used by WEEK() functions + --delay-auto-rotation-on-raft-log-purge + On the leader, when raft logs are being purged delay + automatic log rotation until purge is done even if we go + a beyond the max binlog size. + (Defaults to on; use --skip-delay-auto-rotation-on-raft-log-purge to disable.) --delay-key-write[=name] Type of DELAY_KEY_WRITE --delayed-insert-limit=# @@ -3151,6 +3156,7 @@ default-table-encryption FALSE default-time-zone (No default value) default-tmp-storage-engine InnoDB default-week-format 0 +delay-auto-rotation-on-raft-log-purge TRUE delay-key-write ON delayed-insert-limit 100 delayed-insert-timeout 300 diff --git a/mysql-test/suite/rpl_raft/r/rpl_raft_delay_rotation_on_raft_log_purge.result b/mysql-test/suite/rpl_raft/r/rpl_raft_delay_rotation_on_raft_log_purge.result new file mode 100644 index 000000000000..c985dba20231 --- /dev/null +++ b/mysql-test/suite/rpl_raft/r/rpl_raft_delay_rotation_on_raft_log_purge.result @@ -0,0 +1,52 @@ +include/raft_3_node.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. +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] +include/rpl_connect.inc [creating server_4] +include/rpl_connect.inc [creating server_5] +show status like 'rpl_raft_role'; +Variable_name Value +Rpl_raft_role LEADER +show status like 'rpl_raft_role'; +Variable_name Value +Rpl_raft_role FOLLOWER +reset master; +show status like 'rpl_raft_role'; +Variable_name Value +Rpl_raft_role FOLLOWER +reset master; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +SELECT SLEEP(1); +SLEEP(1) +0 +SET @@GLOBAL.max_binlog_size = 4096; +CREATE TABLE t1(a INT PRIMARY KEY, b TEXT); +SET debug_sync='raft_purge_flag_set SIGNAL purge_reached WAIT_FOR purge_continue'; +PURGE RAFT LOGS BEFORE NOW(); +SET debug_sync='now WAIT_FOR purge_reached'; +INSERT INTO t1 VALUES(1, REPEAT('a', 5000)); +SET debug_sync='now SIGNAL purge_continue'; +Warnings: +Warning 1868 file ./binary-logs-13000.000006 was not purged because it is the active log file. +"There should be only one raft log:" +SHOW RAFT LOGS; +Log_name File_size Encrypted +# # No +INSERT INTO t1 VALUES(2, ""); +"Now we should have two raft logs:" +SHOW RAFT LOGS; +Log_name File_size Encrypted +# # No +# # No +SET @@GLOBAL.max_binlog_size = default; +DROP TABLE t1; +include/sync_slave_sql_with_master.inc +include/sync_slave_sql_with_master.inc +include/rpl_end.inc diff --git a/mysql-test/suite/rpl_raft/t/rpl_raft_delay_rotation_on_raft_log_purge.test b/mysql-test/suite/rpl_raft/t/rpl_raft_delay_rotation_on_raft_log_purge.test new file mode 100644 index 000000000000..18297dcd99fd --- /dev/null +++ b/mysql-test/suite/rpl_raft/t/rpl_raft_delay_rotation_on_raft_log_purge.test @@ -0,0 +1,43 @@ +source include/have_debug_sync.inc; +source ../include/raft_3_node.inc; + +connection server_1; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +FLUSH BINARY LOGS; +SELECT SLEEP(1); + +SET @@GLOBAL.max_binlog_size = 4096; +CREATE TABLE t1(a INT PRIMARY KEY, b TEXT); + +SET debug_sync='raft_purge_flag_set SIGNAL purge_reached WAIT_FOR purge_continue'; +send PURGE RAFT LOGS BEFORE NOW(); + +connection server_1_1; +SET debug_sync='now WAIT_FOR purge_reached'; +INSERT INTO t1 VALUES(1, REPEAT('a', 5000)); +SET debug_sync='now SIGNAL purge_continue'; + +connection server_1; +reap; + +echo "There should be only one raft log:"; +replace_column 1 # 2 #; +SHOW RAFT LOGS; +INSERT INTO t1 VALUES(2, ""); +echo "Now we should have two raft logs:"; +replace_column 1 # 2 #; +SHOW RAFT LOGS; + +# Cleanup +connection server_1; +SET @@GLOBAL.max_binlog_size = default; +DROP TABLE t1; + +let $sync_slave_connection= server_2; +source include/sync_slave_sql_with_master.inc; +let $sync_slave_connection= server_3; +source include/sync_slave_sql_with_master.inc; + +source include/rpl_end.inc; diff --git a/mysql-test/suite/sys_vars/r/delay_auto_rotation_on_raft_log_purge_basic.result b/mysql-test/suite/sys_vars/r/delay_auto_rotation_on_raft_log_purge_basic.result new file mode 100644 index 000000000000..5d4aa5af69e7 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/delay_auto_rotation_on_raft_log_purge_basic.result @@ -0,0 +1,20 @@ +Default value of delay_auto_rotation_on_raft_log_purge is 1 +SELECT @@global.delay_auto_rotation_on_raft_log_purge; +@@global.delay_auto_rotation_on_raft_log_purge +1 +SELECT @@session.delay_auto_rotation_on_raft_log_purge; +ERROR HY000: Variable 'delay_auto_rotation_on_raft_log_purge' is a GLOBAL variable +Expected error 'Variable is a GLOBAL variable' +delay_auto_rotation_on_raft_log_purge is a dynamic variable +SET @@global.delay_auto_rotation_on_raft_log_purge = 1; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; +@@global.delay_auto_rotation_on_raft_log_purge +1 +SET @@global.delay_auto_rotation_on_raft_log_purge = 0; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; +@@global.delay_auto_rotation_on_raft_log_purge +0 +SET @@global.delay_auto_rotation_on_raft_log_purge = default; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; +@@global.delay_auto_rotation_on_raft_log_purge +1 diff --git a/mysql-test/suite/sys_vars/t/delay_auto_rotation_on_raft_log_purge_basic.test b/mysql-test/suite/sys_vars/t/delay_auto_rotation_on_raft_log_purge_basic.test new file mode 100644 index 000000000000..bb2269fefaa8 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/delay_auto_rotation_on_raft_log_purge_basic.test @@ -0,0 +1,27 @@ +-- source include/load_sysvars.inc + +#### +# Verify default value 1 +#### +--echo Default value of delay_auto_rotation_on_raft_log_purge is 1 +SELECT @@global.delay_auto_rotation_on_raft_log_purge; + +#### +# Verify that this is not a session variable # +#### +--Error ER_INCORRECT_GLOBAL_LOCAL_VAR +SELECT @@session.delay_auto_rotation_on_raft_log_purge; +--echo Expected error 'Variable is a GLOBAL variable' + +#### +## Verify that the variable is dynamic +#### +--echo delay_auto_rotation_on_raft_log_purge is a dynamic variable +SET @@global.delay_auto_rotation_on_raft_log_purge = 1; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; + +SET @@global.delay_auto_rotation_on_raft_log_purge = 0; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; + +SET @@global.delay_auto_rotation_on_raft_log_purge = default; +SELECT @@global.delay_auto_rotation_on_raft_log_purge; diff --git a/sql/binlog.cc b/sql/binlog.cc index 04d363b4fcf0..e1a8e4fb9436 100644 --- a/sql/binlog.cc +++ b/sql/binlog.cc @@ -3995,7 +3995,21 @@ bool purge_raft_logs(THD *thd, const char *to_log) { // If mysql_bin_log is not an apply log, then it represents the 'raft logs' on // leader. Call purge_source_logs_to_file() to handle the purge correctly - if (!mysql_bin_log.is_apply_log) return purge_source_logs_to_file(thd, to_log); + if (!mysql_bin_log.is_apply_log) { + mysql_bin_log.is_raft_log_purge_active = true; + const auto start = std::chrono::system_clock::now(); + DEBUG_SYNC(thd, "raft_purge_flag_set"); + bool retval = purge_source_logs_to_file(thd, to_log); + mysql_bin_log.is_raft_log_purge_active = false; + const auto end = std::chrono::system_clock::now(); + sql_print_information( + "Raft log purging was active for %s usecs", + std::to_string( + std::chrono::duration_cast(end - start) + .count()) + .c_str()); + return retval; + } Master_info *active_mi; if (!get_and_lock_master_info(&active_mi)) { @@ -4055,8 +4069,21 @@ bool purge_raft_logs_before_date(THD *thd, time_t purge_time) { // If mysql_bin_log is not an apply log, then it represents the 'raft logs' on // leader. Call purge_source_logs_before_date() to handle the purge // correctly - if (!mysql_bin_log.is_apply_log) - return purge_source_logs_before_date(thd, purge_time); + if (!mysql_bin_log.is_apply_log) { + mysql_bin_log.is_raft_log_purge_active = true; + const auto start = std::chrono::system_clock::now(); + DEBUG_SYNC(thd, "raft_purge_flag_set"); + bool retval = purge_source_logs_before_date(thd, purge_time); + mysql_bin_log.is_raft_log_purge_active = false; + const auto end = std::chrono::system_clock::now(); + sql_print_information( + "Raft log purging was active for %s usecs", + std::to_string( + std::chrono::duration_cast(end - start) + .count()) + .c_str()); + return retval; + } Master_info *active_mi; if (!get_and_lock_master_info(&active_mi)) { @@ -12024,7 +12051,8 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit) { */ if (DBUG_EVALUATE_IF("force_rotate", 1, 0) || (do_rotate && thd->commit_error == THD::CE_NONE && - !is_rotating_caused_by_incident)) { + !is_rotating_caused_by_incident && + (!delay_auto_rotation_on_raft_log_purge || !is_raft_log_purge_active))) { /* Do not force the rotate as several consecutive groups may request unnecessary rotations. diff --git a/sql/binlog.h b/sql/binlog.h index 964f6c0056b4..23201a701160 100644 --- a/sql/binlog.h +++ b/sql/binlog.h @@ -611,6 +611,8 @@ class MYSQL_BIN_LOG : public TC_LOG { uint64_t get_ttl_compaction_ts() const { return ttl_compaction_ts.load(); } + std::atomic is_raft_log_purge_active{false}; + private: /** Checks binlog error action to identify if the server needs to abort on diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 5bcff0aae0dd..9f6cfed78010 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -1252,6 +1252,7 @@ ulong opt_commit_consensus_error_action = 0; bool enable_raft_plugin = 0; bool disallow_raft = 1; // raft is not allowed by default bool override_enable_raft_check = false; +bool delay_auto_rotation_on_raft_log_purge = true; bool abort_on_raft_purge_error = false; ulonglong apply_log_retention_num = 0; ulonglong apply_log_retention_duration = 0; diff --git a/sql/mysqld.h b/sql/mysqld.h index ee941b94c529..c62058eec1ca 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -472,6 +472,7 @@ extern bool disable_raft_log_repointing; extern ulong opt_raft_signal_async_dump_threads; extern bool disallow_raft; extern bool override_enable_raft_check; +extern bool delay_auto_rotation_on_raft_log_purge; extern bool abort_on_raft_purge_error; extern ulonglong apply_log_retention_num; extern ulonglong apply_log_retention_duration; diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc index 1086194f5020..2c577ceeea80 100644 --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -9243,6 +9243,14 @@ static Sys_var_bool Sys_enable_raft_plugin( NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(validate_enable_raft), ON_UPDATE(update_enable_raft_change)); +static Sys_var_bool Sys_delay_auto_rotation_on_raft_log_purge( + "delay_auto_rotation_on_raft_log_purge", + "On the leader, when raft logs are being purged delay automatic log " + "rotation until purge is done even if we go a beyond the max binlog size.", + GLOBAL_VAR(delay_auto_rotation_on_raft_log_purge), CMD_LINE(OPT_ARG), + DEFAULT(true), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(nullptr), + ON_UPDATE(nullptr)); + static Sys_var_bool Sys_abort_on_raft_purge_error( "abort_on_raft_purge_error", "Any error in raft plugin to purge files will abort the server",