MDEV-36159 mariabackup failed after upgrade

Ever since commit 685d958
(MDEV-14425) mariadb-backup --backup had some trouble to keep up
with write workloads of the mariadbd server.

Debarun Banerjee found out that mariadb-backup --backup was
copying the log in the wrong way and not pausing when it made
sense to do so. This change includes his fix as well as some
dead code removal from xtrabackup_copy_mmap_logfile().

Some earlier changes to the default behaviour of mariadb-backup --backup
will be reverted, by making the configuration parameters OFF by default.
These parameters were basically working around this bug:

* commit 652f33e (MDEV-30000)
introduced --innodb-log-checkpoint-now and made it ON by default.
Making the server execute a log checkpoint can be really I/O intensive.
* commit 6acada7 (MDEV-34062)
introduced --innodb-log-file-mmap and made it ON by default on
Linux and FreeBSD. There are no documented semantics what should
happen to a memory mapping when there are concurrent pwrite(2)
operations by other processes. While it appears to work, it is safer
to default to clearly documented semantics.

xtrabackup_copy_logfile(): Add a parameter early_exit.
Always read a log snippet to the start of recv_sys.buf and assign
recv_sys.len to the read length. We used to shift recv_sys.buf
with memmove(). However, on recv_sys_t::PREMATURE_EOF we cannot know
which part of the mini-transaction was correctly read, because that
part of the ib_logfile0 may be concurrently modified by the server.
So, we will reread everything from the start of the mini-transaction.

xtrabackup_backup_func(): Invoke xtrabackup_copy_logfile(true),
allowing it to stop on every recv_sys_t::PREMATURE_EOF.
This will also avoid repeated "Retry" messages when there is no
more redo log to copy.

get_current_lsn(): Execute FLUSH ENGINE LOGS to ensure that
InnoDB will complete any buffered writes to the ib_logfile0
and ensure that everything up to the current LSN has been
written.

backup_wait_for_commit_lsn(): Wait for as much as is really needed.
This avoids an extra 5-second wait at the end of the backup.

xtrabackup_copy_mmap_logfile(): Remove some dead code, and add
debug assertions to demonstrate that the parser can only return
recv_sys_t::OK or recv_sys_t::GOT_EOF.

Author: dr-m

extra/mariabackup/backup_mysql.cc

@@ -2068,6 +2068,7 @@ ulonglong get_current_lsn(MYSQL *connection)
 {
 	static const char lsn_prefix[] = "\nLog sequence number ";
 	ulonglong lsn = 0;
+	msg("Getting InnoDB LSN");
 	if (MYSQL_RES *res = xb_mysql_query(connection,
 					    "SHOW ENGINE INNODB STATUS",
 					    true, false)) {
@@ -2081,5 +2082,10 @@ ulonglong get_current_lsn(MYSQL *connection)
 		}
 		mysql_free_result(res);
 	}
+	msg("InnoDB LSN: %llu, Flushing Logs", lsn);
+        /* Make sure that current LSN is written and flushed to disk. */
+	xb_mysql_query(connection, "FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS",
+		       false, false);
+	msg("Flushed Logs");
 	return lsn;
 }

extra/mariabackup/xtrabackup.cc

@@ -1957,7 +1957,7 @@ struct my_option xb_server_options[] =
    "Whether ib_logfile0 should be memory-mapped",
    (G_PTR*) &log_sys.log_mmap,
    (G_PTR*) &log_sys.log_mmap, 0, GET_BOOL, NO_ARG,
-   log_sys.log_mmap_default, 0, 0, 0, 0, 0},
+   FALSE, 0, 0, 0, 0, 0},
 #if defined __linux__ || defined _WIN32
   {"innodb_log_file_buffering", OPT_INNODB_LOG_FILE_BUFFERING,
    "Whether the file system cache for ib_logfile0 is enabled during --backup",
@@ -2086,7 +2086,7 @@ struct my_option xb_server_options[] =
    "(for --backup): Force an InnoDB checkpoint",
    (G_PTR*)&innodb_log_checkpoint_now,
    (G_PTR*)&innodb_log_checkpoint_now,
-   0, GET_BOOL, OPT_ARG, 1, 0, 0, 0, 0, 0},
+   0, GET_BOOL, OPT_ARG, 0, 0, 0, 0, 0, 0},
 
     {"mysqld-args", OPT_XTRA_MYSQLD_ARGS,
      "All arguments that follow this argument are considered as server "
@@ -3438,87 +3438,53 @@ static bool xtrabackup_copy_mmap_logfile()
   recv_sys.len= size_t(log_sys.file_size);
   const size_t seq_offset{log_sys.is_encrypted() ? 8U + 5U : 5U};
   const char one{'\1'};
+  const byte *start= &log_sys.buf[recv_sys.offset];
+  ut_d(recv_sys_t::parse_mtr_result r);
 
-  for (unsigned retry_count{0};;)
+  if ((ut_d(r=) recv_sys.parse_mmap<recv_sys_t::store::BACKUP>(false)) ==
+      recv_sys_t::OK)
   {
-    recv_sys_t::parse_mtr_result r;
-    const byte *start= &log_sys.buf[recv_sys.offset];
-
-    if (recv_sys.parse_mmap<recv_sys_t::store::BACKUP>(false) ==
-        recv_sys_t::OK)
+    do
     {
-      const byte *end;
-
-      do
+      /* Set the sequence bit (the backed-up log will not wrap around) */
+      size_t seqo= recv_sys.offset - seq_offset;
+      if (seqo < log_sys.START_OFFSET)
+        seqo+= static_cast<size_t>(log_sys.file_size - log_sys.START_OFFSET);
+      const byte *seq= &log_sys.buf[seqo];
+      ut_ad(*seq == log_sys.get_sequence_bit(recv_sys.lsn - seq_offset));
+      if (!*seq)
       {
-        /* Set the sequence bit (the backed-up log will not wrap around) */
-        size_t seqo= recv_sys.offset - seq_offset;
-        if (seqo < log_sys.START_OFFSET)
-          seqo+= static_cast<size_t>(log_sys.file_size - log_sys.START_OFFSET);
-        const byte *seq= &log_sys.buf[seqo];
-        ut_ad(*seq == log_sys.get_sequence_bit(recv_sys.lsn - seq_offset));
-        if (!*seq)
-        {
-          if (xtrabackup_copy_mmap_snippet(dst_log_file, start, seq) ||
-              ds_write(dst_log_file, &one, 1))
-            goto write_error;
-          start = seq + 1;
-        }
+        if (xtrabackup_copy_mmap_snippet(dst_log_file, start, seq) ||
+            ds_write(dst_log_file, &one, 1))
+          goto write_error;
+        start = seq + 1;
       }
-      while ((r= recv_sys.parse_mmap<recv_sys_t::store::BACKUP>(false)) ==
-             recv_sys_t::OK);
-
-      end= &log_sys.buf[recv_sys.offset];
-
-      if (xtrabackup_copy_mmap_snippet(dst_log_file, start, end))
-      {
-      write_error:
-        msg("Error: write to ib_logfile0 failed");
-        return true;
-      }
-
-      start= end;
-
-      pthread_cond_broadcast(&scanned_lsn_cond);
-
-      if (r == recv_sys_t::GOT_EOF)
-        break;
-
-      retry_count= 0;
     }
-    else
-    {
-      if (metadata_to_lsn)
-      {
-        if (metadata_to_lsn <= recv_sys.lsn)
-          return false;
-      }
-      else if (xtrabackup_throttle && io_ticket-- < 0)
-        mysql_cond_wait(&wait_throttle, &recv_sys.mutex);
+    while ((ut_d(r=) recv_sys.parse_mmap<recv_sys_t::store::BACKUP>(false)) ==
+           recv_sys_t::OK);
 
-      if (!retry_count++)
-        msg("Retrying read of log at LSN=" LSN_PF, recv_sys.lsn);
-      else if (retry_count == 100)
-        break;
-      else
-      {
-        timespec abstime;
-        set_timespec_nsec(abstime, 1000000ULL /* 1 ms */);
-        if (!mysql_cond_timedwait(&log_copying_stop, &recv_sys.mutex,
-                                  &abstime))
-          return true;
-      }
+    if (xtrabackup_copy_mmap_snippet(dst_log_file, start,
+                                     &log_sys.buf[recv_sys.offset]))
+    {
+    write_error:
+      msg("Error: write to ib_logfile0 failed");
+      return true;
     }
+
+    pthread_cond_broadcast(&scanned_lsn_cond);
   }
 
+  ut_ad(r == recv_sys_t::GOT_EOF);
+
   if (verbose)
     msg(">> log scanned up to (" LSN_PF ")", recv_sys.lsn);
   return false;
 }
 
 /** Copy redo log until the current end of the log is reached
+@param early_exit parse and copy only logs from first read and return
 @return whether the operation failed */
-static bool xtrabackup_copy_logfile()
+static bool xtrabackup_copy_logfile(bool early_exit)
 {
   mysql_mutex_assert_owner(&recv_sys.mutex);
   DBUG_EXECUTE_IF("log_checksum_mismatch", return false;);
@@ -3534,20 +3500,19 @@ static bool xtrabackup_copy_logfile()
 
   recv_sys.offset= size_t(recv_sys.lsn - log_sys.get_first_lsn()) &
     block_size_1;
-  recv_sys.len= 0;
 
   for (unsigned retry_count{0};;)
   {
     recv_sys_t::parse_mtr_result r;
     size_t start_offset{recv_sys.offset};
 
     {
+      recv_sys.len= 0;
       {
         auto source_offset=
-          log_sys.calc_lsn_offset(recv_sys.lsn + recv_sys.len -
-                                  recv_sys.offset);
+          log_sys.calc_lsn_offset(recv_sys.lsn - recv_sys.offset);
         source_offset&= ~block_size_1;
-        size_t size{log_sys.buf_size - recv_sys.len};
+        size_t size{log_sys.buf_size};
         if (UNIV_UNLIKELY(source_offset + size > log_sys.file_size))
         {
           const size_t first{size_t(log_sys.file_size - source_offset)};
@@ -3589,32 +3554,25 @@ static bool xtrabackup_copy_logfile()
           msg("Error: write to ib_logfile0 failed");
           return true;
         }
-        else
-        {
-          const auto ofs= recv_sys.offset & ~block_size_1;
-          memmove_aligned<64>(log_sys.buf, log_sys.buf + ofs,
-                              recv_sys.len - ofs);
-          recv_sys.len-= ofs;
-          recv_sys.offset&= block_size_1;
-        }
-
         pthread_cond_broadcast(&scanned_lsn_cond);
 
-        if (r == recv_sys_t::GOT_EOF)
+        if (r == recv_sys_t::GOT_EOF || early_exit)
           break;
 
+        ut_ad(r == recv_sys_t::PREMATURE_EOF);
+
         if (recv_sys.offset < log_sys.write_size)
           break;
 
         if (xtrabackup_throttle && io_ticket-- < 0)
           mysql_cond_wait(&wait_throttle, &recv_sys.mutex);
 
+        recv_sys.offset&= block_size_1;
         retry_count= 0;
         continue;
       }
       else
       {
-        recv_sys.len= recv_sys.offset & ~block_size_1;
         if (retry_count == 100)
           break;
 
@@ -3694,7 +3652,7 @@ static void log_copying_thread()
 {
   my_thread_init();
   mysql_mutex_lock(&recv_sys.mutex);
-  while (!xtrabackup_copy_logfile() &&
+  while (!xtrabackup_copy_logfile(false) &&
          (!metadata_last_lsn || metadata_last_lsn > recv_sys.lsn))
   {
     timespec abstime;
@@ -4912,7 +4870,7 @@ static bool backup_wait_for_commit_lsn()
   ut_ad(metadata_to_lsn);
   metadata_last_lsn= lsn;
 
-  last_lsn= backup_wait_for_lsn_low(LSN_MAX);
+  last_lsn= backup_wait_for_lsn_low(lsn);
 
   metadata_last_lsn= last_lsn;
   stop_backup_threads();
@@ -5468,12 +5426,14 @@ static bool xtrabackup_backup_func()
 	}
 	msg("cd to %s", mysql_real_data_home);
 	encryption_plugin_backup_init(mysql_connection);
-	if (innodb_log_checkpoint_now != false && mysql_send_query(
-		    mysql_connection,
+	if (innodb_log_checkpoint_now) {
+		msg("Initiating checkpoint");
+		if (mysql_send_query(mysql_connection,
 		    C_STRING_WITH_LEN("SET GLOBAL "
 				      "innodb_log_checkpoint_now=ON;"))) {
-		msg("initiating checkpoint failed");
-		return(false);
+			msg("initiating checkpoint failed");
+			return(false);
+		}
 	}
 
 	msg("open files limit requested %lu, set to %lu",
@@ -5587,6 +5547,7 @@ static bool xtrabackup_backup_func()
 	server does not support this */
 	if (innodb_log_checkpoint_now != false) {
 		mysql_read_query_result(mysql_connection);
+		msg("Finished waiting for checkpoint");
 	}
 
 	if (!select_history()) {
@@ -5626,7 +5587,7 @@ static bool xtrabackup_backup_func()
 	mysql_mutex_lock(&recv_sys.mutex);
 	recv_sys.lsn = log_sys.next_checkpoint_lsn;
 
-	const bool log_copy_failed = xtrabackup_copy_logfile();
+	const bool log_copy_failed = xtrabackup_copy_logfile(true);
 
 	mysql_mutex_unlock(&recv_sys.mutex);
 

mysql-test/suite/mariabackup/full_backup.test

@@ -10,7 +10,7 @@ let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
 --disable_result_log
 --error 1
 exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir --parallel=10 --innodb-log-write-ahead-size=4095 > $backup_log 2>&1;
-exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir --parallel=10 --innodb-log-write-ahead-size=10000 > $backup_log 2>&1;
+exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir --parallel=10 --innodb-log-write-ahead-size=10000 --innodb_log_checkpoint_now=1 > $backup_log 2>&1;
 --enable_result_log
 
 # The following warning must not appear after MDEV-27343 fix

mysql-test/suite/mariabackup/partial.test

@@ -14,7 +14,7 @@ echo # xtrabackup backup;
 
 let targetdir=$MYSQLTEST_VARDIR/tmp/backup;
 --disable_result_log
-exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables=test.*1" --target-dir=$targetdir;
+exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables=test.*1" --target-dir=$targetdir --innodb_log_checkpoint_now=1;
 --enable_result_log
 list_files $targetdir/test *.ibd;
 list_files $targetdir/test *.new;
@@ -96,6 +96,7 @@ exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --tables-file
 --enable_result_log
 
 --echo # table t2 is skipped. Shows only t1
+--replace_result .new .ibd
 list_files $targetdir/test;
 DROP TABLE t2, t1;
 rmdir $targetdir;

mysql-test/suite/mariabackup/partial_exclude.test

@@ -28,7 +28,7 @@ echo # xtrabackup backup;
 
 let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
 --disable_result_log
-exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables-exclude=test.*2" "--databases-exclude=db2" --target-dir=$targetdir;
+exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables-exclude=test.*2" "--databases-exclude=db2" --target-dir=$targetdir --innodb_log_checkpoint_now=1;
 --enable_result_log
 
 COMMIT;

mysql-test/suite/mariabackup/unsupported_redo.test

@@ -58,7 +58,7 @@ ALTER TABLE t21 FORCE, ALGORITHM=INPLACE;
 --echo # unsupported redo log for the table t21.
 
 --disable_result_log
-exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables-exclude=test.t21" --target-dir=$targetdir;
+exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --parallel=10 "--tables-exclude=test.t21" --target-dir=$targetdir --innodb_log_checkpoint_now=1;
 --enable_result_log
 --list_files $targetdir/test *.ibd
 --list_files $targetdir/test *.new