Bug#19424075 WRITE/SYNC REDO LOG BEFORE FLUSH THREAD CACHE TO BINLOG

According to the crash recovery logic of mysql server, we only
need to guarantee that write/sync prepared transaction to InnoDB
redo log before writing to binary log. And prepared records of
transactions were not committed into InnoDB redo log in a group.

To improve performance, write/sync prepared records of transactions
to InnoDB redo log in a group right before writing to binary log
during binlog group commit flush stage.

Author: Bill Qu

mysql-test/r/mysqld--help-notwin.result

@@ -85,11 +85,6 @@ The following options may be given as the first argument:
  --binlog-ignore-db=name 
  Tells the master that updates to the given database
  should not be logged to the binary log.
- --binlog-max-flush-queue-time=# 
- The maximum time that the binary log group commit will
- keep reading transactions before it flush the
- transactions to the binary log (and optionally sync,
- depending on the value of sync_binlog).
  --binlog-order-commits 
  Issue internal commit calls in the same order as
  transactions are written to the binary log. Default is to
@@ -1119,7 +1114,6 @@ binlog-error-action IGNORE_ERROR
 binlog-format STATEMENT
 binlog-group-commit-sync-delay 0
 binlog-group-commit-sync-no-delay-count 0
-binlog-max-flush-queue-time 0
 binlog-order-commits TRUE
 binlog-row-event-max-size 8192
 binlog-row-image FULL

mysql-test/r/mysqld--help-win.result

@@ -85,11 +85,6 @@ The following options may be given as the first argument:
  --binlog-ignore-db=name 
  Tells the master that updates to the given database
  should not be logged to the binary log.
- --binlog-max-flush-queue-time=# 
- The maximum time that the binary log group commit will
- keep reading transactions before it flush the
- transactions to the binary log (and optionally sync,
- depending on the value of sync_binlog).
  --binlog-order-commits 
  Issue internal commit calls in the same order as
  transactions are written to the binary log. Default is to
@@ -1119,7 +1114,6 @@ binlog-error-action IGNORE_ERROR
 binlog-format STATEMENT
 binlog-group-commit-sync-delay 0
 binlog-group-commit-sync-no-delay-count 0
-binlog-max-flush-queue-time 0
 binlog-order-commits TRUE
 binlog-row-event-max-size 8192
 binlog-row-image FULL

mysql-test/suite/binlog/r/binlog_group_commit_flush_crash.result

@@ -0,0 +1,28 @@
+CREATE TABLE t1(c1 INT) ENGINE= InnoDB;
+# Crash right after flushing InnoDB redo log
+SET SESSION DEBUG="+d,crash_after_flush_engine_log";
+BEGIN;
+INSERT INTO t1 VALUES(1);
+COMMIT;
+ERROR HY000: Lost connection to MySQL server during query
+# Restart the master server
+#
+# Verify that a transaction can not be recovered during server
+# recovery from a crash, which happened after flushing it to
+# InnoDB redo log and before flushing it to binary log.
+#
+include/assert.inc [Table t1 must not contain 1]
+# Crash right after flushing binary log
+SET SESSION DEBUG="+d,crash_after_flush_binlog";
+BEGIN;
+INSERT INTO t1 VALUES(2);
+COMMIT;
+ERROR HY000: Lost connection to MySQL server during query
+# Restart the master server
+#
+# Verify that a transaction can be recovered during server
+# recovery from a crash, which happened after flushing it
+# to binary log.
+#
+include/assert.inc [Table t1 must contain 2]
+DROP TABLE t1;

mysql-test/suite/binlog/t/binlog_group_commit_flush_crash.test

@@ -0,0 +1,67 @@
+#
+# Bug#19424075 	WRITE/SYNC REDO LOG BEFORE FLUSH THREAD CACHE TO BINLOG
+#
+# Verify that a transaction can not be recovered during server
+# recovery from a crash, which happened after flushing it to
+# InnoDB redo log and before flushing it to binary log. And
+# a transaction can be recovered during server recovery from
+# a crash, which happened after flushing it to binary log.
+#
+--source include/not_embedded.inc
+--source include/not_valgrind.inc
+--source include/have_log_bin.inc
+
+CREATE TABLE t1(c1 INT) ENGINE= InnoDB;
+
+--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--echo # Crash right after flushing InnoDB redo log
+SET SESSION DEBUG="+d,crash_after_flush_engine_log";
+BEGIN;
+INSERT INTO t1 VALUES(1);
+# 2013 - CR_SERVER_LOST
+--error 2013
+COMMIT;
+--source include/wait_until_disconnected.inc
+
+--enable_reconnect
+--echo # Restart the master server
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--source include/wait_until_connected_again.inc
+--disable_reconnect
+
+--echo #
+--echo # Verify that a transaction can not be recovered during server
+--echo # recovery from a crash, which happened after flushing it to
+--echo # InnoDB redo log and before flushing it to binary log.
+--echo #
+--let $assert_text= Table t1 must not contain 1
+--let $assert_cond= [SELECT count(*) FROM t1 WHERE c1=1] = 0
+--source include/assert.inc
+
+--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--echo # Crash right after flushing binary log
+SET SESSION DEBUG="+d,crash_after_flush_binlog";
+BEGIN;
+INSERT INTO t1 VALUES(2);
+# 2013 - CR_SERVER_LOST
+--error 2013
+COMMIT;
+--source include/wait_until_disconnected.inc
+
+--enable_reconnect
+--echo # Restart the master server
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--source include/wait_until_connected_again.inc
+--disable_reconnect
+
+--echo #
+--echo # Verify that a transaction can be recovered during server
+--echo # recovery from a crash, which happened after flushing it
+--echo # to binary log.
+--echo #
+--let $assert_text= Table t1 must contain 2
+--let $assert_cond= [SELECT count(*) FROM t1 WHERE c1=2] = 1
+--source include/assert.inc
+
+# Cleanup
+DROP TABLE t1;

mysql-test/suite/rpl/t/rpl_binlog_gcommit_options-master.opt

@@ -1 +1 @@
---binlog-max-flush-queue-time=1 --skip-binlog-order-commits
+--skip-binlog-order-commits

mysql-test/suite/rpl/t/rpl_group_commit_binlog_flush_crash-master.opt

@@ -0,0 +1 @@
+--sync-binlog=1 --innodb-flush-log-at-trx-commit=1

mysql-test/suite/sys_vars/r/binlog_max_flush_queue_time_basic.result

@@ -15,14 +15,14 @@ time_zone,autocommit,character_set_client,character_set_results,character_set_co
 SELECT * FROM INFORMATION_SCHEMA.GLOBAL_VARIABLES WHERE VARIABLE_NAME LIKE 'session_track%';
 VARIABLE_NAME	VARIABLE_VALUE
 SESSION_TRACK_SCHEMA	ON
-SESSION_TRACK_SYSTEM_VARIABLES	time_zone,autocommit,character_set_client,character_set_results,character_set_connection
 SESSION_TRACK_STATE_CHANGE	OFF
+SESSION_TRACK_SYSTEM_VARIABLES	time_zone,autocommit,character_set_client,character_set_results,character_set_connection
 # via INFORMATION_SCHEMA.SESSION_VARIABLES
 SELECT * FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE VARIABLE_NAME LIKE 'session_track%';
 VARIABLE_NAME	VARIABLE_VALUE
 SESSION_TRACK_SCHEMA	ON
-SESSION_TRACK_SYSTEM_VARIABLES	time_zone,autocommit,character_set_client,character_set_results,character_set_connection
 SESSION_TRACK_STATE_CHANGE	OFF
+SESSION_TRACK_SYSTEM_VARIABLES	time_zone,autocommit,character_set_client,character_set_results,character_set_connection
 SET @global_saved_tmp =  @@global.session_track_system_variables;
 
 # Altering global variable's value

mysql-test/suite/sys_vars/r/session_track_system_variables_basic.result

@@ -6953,6 +6953,25 @@ int MYSQL_BIN_LOG::prepare(THD *thd, bool all)
 {
   DBUG_ENTER("MYSQL_BIN_LOG::prepare");
 
+  DBUG_ASSERT(opt_bin_log);
+  /*
+    The applier thread explicitly overrides the value of sql_log_bin
+    with the value of log_slave_updates.
+  */
+  DBUG_ASSERT(thd->slave_thread ?
+              opt_log_slave_updates : thd->variables.sql_log_bin);
+
+  /*
+    Set HA_IGNORE_DURABILITY to not flush the prepared record of the
+    transaction to the log of storage engine (for example, InnoDB
+    redo log) during the prepare phase. So that we can flush prepared
+    records of transactions to the log of storage engine in a group
+    right before flushing them to binary log during binlog group
+    commit flush stage. Reset to HA_REGULAR_DURABILITY at the
+    beginning of parsing next command.
+  */
+  thd->durability_property= HA_IGNORE_DURABILITY;
+
   int error= ha_prepare_low(thd, all);
 
   DBUG_RETURN(error);
@@ -7221,55 +7240,33 @@ MYSQL_BIN_LOG::process_flush_stage_queue(my_off_t *total_bytes_var,
   int flush_error= 1;
   mysql_mutex_assert_owner(&LOCK_log);
 
-  const ulonglong max_udelay= my_atomic_load32(&opt_binlog_max_flush_queue_time);
-  const ulonglong start_utime= max_udelay > 0 ? my_micro_time() : 0;
-
   /*
-    First we read the queue until it either is empty or the difference
-    between the time we started and the current time is too large.
-
-    We remember the first thread we unqueued, because this will be the
-    beginning of the out queue.
-   */
-  bool has_more= true;
-  THD *first_seen= NULL;
-  while ((max_udelay == 0 || my_micro_time() < start_utime + max_udelay) && has_more)
+    Fetch the entire flush queue and empty it, so that the next batch
+    has a leader. We must do this before invoking ha_flush_logs(...)
+    for guaranteeing to flush prepared records of transactions before
+    flushing them to binary log, which is required by crash recovery.
+  */
+  THD *first_seen= stage_manager.fetch_queue_for(Stage_manager::FLUSH_STAGE);
+  DBUG_ASSERT(first_seen != NULL);
+  /*
+    We flush prepared records of transactions to the log of storage
+    engine (for example, InnoDB redo log) in a group right before
+    flushing them to binary log.
+  */
+  ha_flush_logs(NULL, true);
+  DBUG_EXECUTE_IF("crash_after_flush_engine_log", DBUG_SUICIDE(););
+  /* Flush thread caches to binary log. */
+  for (THD *head= first_seen ; head ; head = head->next_to_commit)
   {
-    std::pair<bool,THD*> current= stage_manager.pop_front(Stage_manager::FLUSH_STAGE);
-    std::pair<int,my_off_t> result= flush_thread_caches(current.second);
-    has_more= current.first;
+    std::pair<int,my_off_t> result= flush_thread_caches(head);
     total_bytes+= result.second;
     if (flush_error == 1)
       flush_error= result.first;
-    if (first_seen == NULL)
-      first_seen= current.second;
 #ifndef DBUG_OFF
     no_flushes++;
 #endif
   }
 
-  /*
-    Either the queue is empty, or we ran out of time. If we ran out of
-    time, we have to fetch the entire queue (and flush it) since
-    otherwise the next batch will not have a leader.
-   */
-  if (has_more)
-  {
-    THD *queue= stage_manager.fetch_queue_for(Stage_manager::FLUSH_STAGE);
-    for (THD *head= queue ; head ; head = head->next_to_commit)
-    {
-      std::pair<int,my_off_t> result= flush_thread_caches(head);
-      total_bytes+= result.second;
-      if (flush_error == 1)
-        flush_error= result.first;
-#ifndef DBUG_OFF
-      no_flushes++;
-#endif
-    }
-    if (first_seen == NULL)
-      first_seen= queue;
-  }
-
   *out_queue_var= first_seen;
   *total_bytes_var= total_bytes;
   if (total_bytes > 0 && my_b_tell(&log_file) >= (my_off_t) max_size)
@@ -7744,6 +7741,7 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit)
   my_off_t flush_end_pos= 0;
   if (flush_error == 0 && total_bytes > 0)
     flush_error= flush_cache_to_file(&flush_end_pos);
+  DBUG_EXECUTE_IF("crash_after_flush_binlog", DBUG_SUICIDE(););
 
   bool update_binlog_end_pos_after_sync= (get_sync_period() == 1);
 

mysql-test/suite/sys_vars/t/binlog_max_flush_queue_time_basic.test

@@ -852,11 +852,18 @@ static void ndbcluster_reset_slave(THD *thd)
 /**
   Upon the sql command flush logs, we need to ensure that all outstanding
   ndb data to be logged has made it to the binary log to get a deterministic
-  behavior on the rotation of the log.
+  behavior on the rotation of the log. Do nothing if the ndbcluster_flush_logs
+  is caused by binlog group commit during flush stage.
+
+  @param hton NDB handlerton.
+  @param binlog_group_flush true if we got invoked by binlog group
+  commit during flush stage, false in other cases.
+  @return false Success always.
  */
-static bool ndbcluster_flush_logs(handlerton *hton)
+static bool ndbcluster_flush_logs(handlerton *hton, bool binlog_group_flush)
 {
-  ndbcluster_binlog_wait(current_thd);
+  if (!binlog_group_flush)
+    ndbcluster_binlog_wait(current_thd);
   return FALSE;
 }
 

sql/binlog.cc

@@ -2165,25 +2165,27 @@ static my_bool flush_handlerton(THD *thd, plugin_ref plugin,
                                 void *arg)
 {
   handlerton *hton= plugin_data(plugin, handlerton *);
-  if (hton->state == SHOW_OPTION_YES && hton->flush_logs && 
-      hton->flush_logs(hton))
+  if (hton->state == SHOW_OPTION_YES && hton->flush_logs &&
+      hton->flush_logs(hton, *(static_cast<bool *>(arg))))
     return TRUE;
   return FALSE;
 }
 
 
-bool ha_flush_logs(handlerton *db_type)
+bool ha_flush_logs(handlerton *db_type, bool binlog_group_flush)
 {
   if (db_type == NULL)
   {
     if (plugin_foreach(NULL, flush_handlerton,
-                          MYSQL_STORAGE_ENGINE_PLUGIN, 0))
+                       MYSQL_STORAGE_ENGINE_PLUGIN,
+                       static_cast<void *>(&binlog_group_flush)))
       return TRUE;
   }
   else
   {
     if (db_type->state != SHOW_OPTION_YES ||
-        (db_type->flush_logs && db_type->flush_logs(db_type)))
+        (db_type->flush_logs &&
+         db_type->flush_logs(db_type, binlog_group_flush)))
       return TRUE;
   }
   return FALSE;