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: f51a654

---------------------------------------------------------------------

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: abd2ecc

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

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

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;

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

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;

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<std::chrono::microseconds>(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<std::chrono::microseconds>(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.

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<bool> is_raft_log_purge_active{false};
+
  private:
  /**
  Checks binlog error action to identify if the server needs to abort on

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;

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;

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",