Merge lp:~akopytov/percona-xtrabackup/BT27412-bug1055989-2.0 into lp:percona-xtrabackup/2.0

[Alexey Kopytov]

    Bug #1055989: innobackupex waits for streaming temporary log file to
                  finish before unlocking tables

    The problem was that in XtraBackup 2.0 streaming xtrabackup_logfile from
    a temporary file was performed in the xtrabackup binary and
    innobackupex waited for the xtrabackup process to exit before unlocking
    the tables. Streaming the log file might take a long time, while
    unnecessarily keeping the server locked with FTWRL. In fact, releasing
    the lock can be performed as soon as the xtrabackup binary stops
    duplicating the redo log.

    Fixed by:

    - splitting resume_ibbackup() into two functions. resume_ibbackup()
      itself now resumes the xtrabackup process and then just waits for the
      log copying to stop rather than process termination as previously. The
      new function wait_for_ibbackup_finish() now waits for process
      termination and obtains its exit status. This function is called after
      releasing the FTWRL lock.

    - implementing a new synchronization point between innobackupex and
      xtrabackup using the same mechanism (the xtrabackup_suspended file)
      which is used for synchronization before starting FTWRL: when
      innobackupex wants to wait until log copying finishes, it removes
      xtrabackup_suspended and waits until it is created again by
      xtrabackup. So xtrabackup creates the file to signal innobackupex when
      log copying is complete and it is now safe to release the FTWRL lock.

[Alexey Kopytov (akopytov)]

http://jenkins.percona.com/view/XtraBackup/job/percona-xtrabackup-2.0-param/303/

[Laurynas Biveinis (laurynas-biveinis)]

Alexey -

The patch is OK with one point: the second use of xtrabackup_suspended file has nothing to do with xtrabackup being suspended when it's created. Also I have a feature in works that suspends/resumes XB at a different point. I think it's a good idea to have unique file names for all the "sync points": avoid "wires-crossed" sync bugs (it's hard to imagine how one could happen currently, but who what else we will develop before we merge IB and XB :), help with troubleshooting if XB crashed and there's a directory listing only, etc.

review: Needs Fixing

[Alexey Kopytov (akopytov)]

Laurynas,

Thanks for the review. I agree there are currently no problems caused by reusing xtrabackup_suspended file, though the name looks a bit confusing. I could rename it to xtrabackup_lock or something, but I try to do small incremental changes, and not change something unless I absolutely have to.

It does the job for this specific fix. In case we need more fine-grained locking (before merging innobackupex and xtrabackup), we may consider adding more lock files in the future.

Setting to approved, as there are no comments other than those about the lock file name.

review: Approve

=== modified file 'innobackupex'
--- innobackupex	2012-11-07 06:44:45 +0000
+++ innobackupex	2012-11-15 09:01:29 +0000
@@ -425,12 +425,14 @@
     # (or finalize the backup by syncing changes if using rsync)
     backup_files(0);
 
-    # resume ibbackup and wait till it has finished
-    my $ibbackup_exit_code = resume_ibbackup();
+    # resume ibbackup and wait till log copying is finished
+    resume_ibbackup();
 
     # release read locks on all tables
     mysql_unlockall() if !$option_no_lock;
 
+    my $ibbackup_exit_code = wait_for_ibbackup_finish();
+
     if ( $option_safe_slave_backup && $sql_thread_started) {
       print STDERR "$prefix: Starting slave SQL thread\n";
       mysql_send('START SLAVE SQL_THREAD;');
@@ -921,12 +923,56 @@
 
 
 #
-# resume_ibbackup subroutine signals ibbackup to complete its execution
-# by deleting the 'ibbackup_suspended' file.
+# resume_ibbackup subroutine signals ibbackup to finish log copying by deleting
+# the 'xtrabackup_suspended' file and waits until log copying is stopped,
+# i.e. until 'xtrabackup_suspended' is created again.
+#
+# If this functions detects that the xtrabackup process has terminated, it also
+# sets ibbackup_exit_code and resets ibbackup_pid to avoid trying to reap a
+# non-existing process later
 #
 sub resume_ibbackup {
-    print STDERR "$prefix Resuming ibbackup\n\n";
-    unlink $suspend_file || Die "Failed to delete '$suspend_file': $!";
+    my $pid = -1;
+
+    $now = current_time();
+    print STDERR "$now  $prefix Waiting for log copying to finish\n\n";
+    unlink $suspend_file || Die "Failed to delete '$suspend_file': $!";
+
+    for (;;) {
+        # check if the xtrabackup process is still alive _before_ checking if
+        # the file exists to avoid a race condition when the file is created and
+        # the process terminates right after we do the file check
+        $pid = waitpid($ibbackup_pid, &WNOHANG);
+
+        last if -e $suspend_file;
+
+        if ($ibbackup_pid == $pid) {
+            # The file doesn't exist, but the process has terminated
+            Die "ibbackup child process has died";
+        }
+
+        sleep 1;
+    }
+
+    if ($pid == $ibbackup_pid) {
+        $ibbackup_exit_code = $CHILD_ERROR >> 8;
+        $ibbackup_pid = '';
+    }
+
+    unlink $suspend_file || Die "Failed to delete '$suspend_file': $!";
+}
+
+#
+# wait for ibbackup to finish and return its exit code
+#
+sub wait_for_ibbackup_finish {
+    if (!$ibbackup_pid) {
+        # The process has already been reaped.
+        return $ibbackup_exit_code;
+    }
+
+    $now = current_time();
+    print STDERR "$now  $prefix Waiting for ibbackup (pid=$ibbackup_pid) to finish\n";
 
     # wait for ibbackup to finish
     waitpid($ibbackup_pid, 0);
 
=== modified file 'src/xtrabackup.c'
--- src/xtrabackup.c	2012-11-08 23:42:03 +0000
+++ src/xtrabackup.c	2012-11-15 09:01:29 +0000
@@ -4195,6 +4195,32 @@
 	return(TRUE);
 }
 
+/***********************************************************************
+Create an empty file with a given path and close it.
+@return TRUE on succees, FALSE on error. */
+static ibool
+xb_create_suspend_file(const char *path)
+{
+	ibool			success;
+	os_file_t		suspend_file = XB_FILE_UNDEFINED;
+
+	/* xb_file_create reads srv_unix_file_flush_method */
+	suspend_file = xb_file_create(path, OS_FILE_CREATE,
+				      OS_FILE_NORMAL, OS_DATA_FILE,
+				      &success);
+
+	if (success && suspend_file != XB_FILE_UNDEFINED) {
+
+		os_file_close(suspend_file);
+
+		return(TRUE);
+	}
+
+	msg("xtrabackup: Error: failed to create file '%s'\n", path);
+
+	return(FALSE);
+}
+
 static void
 xtrabackup_backup_func(void)
 {
@@ -4204,6 +4230,8 @@
 	datasink_t		*ds;
 	ds_ctxt_t		*ds_ctxt = NULL;
 	ds_ctxt_t		*meta_ds_ctxt;
+	char			suspend_path[FN_REFLEN];
+	ibool			success;
 
 #ifdef USE_POSIX_FADVISE
 	msg("xtrabackup: uses posix_fadvise().\n");
@@ -4648,36 +4676,25 @@
 
 	/* suspend-at-end */
 	if (xtrabackup_suspend_at_end) {
-		os_file_t	suspend_file = XB_FILE_UNDEFINED;
-		char	suspend_path[FN_REFLEN];
-		ibool	success, exists;
+		ibool		exists;
 		os_file_type_t	type;
 
 		sprintf(suspend_path, "%s%s", xtrabackup_target_dir,
 			"/xtrabackup_suspended");
-
 		srv_normalize_path_for_win(suspend_path);
-		/* xb_file_create reads srv_unix_file_flush_method */
-		suspend_file = xb_file_create(suspend_path, OS_FILE_OVERWRITE,
-					      OS_FILE_NORMAL, OS_DATA_FILE,
-					      &success);
 
-		if (!success) {
-			msg("xtrabackup: Error: failed to create file "
-			    "'xtrabackup_suspended'\n");
+		if (!xb_create_suspend_file(suspend_path)) {
+			exit(EXIT_FAILURE);
 		}
 
-		if (suspend_file != XB_FILE_UNDEFINED)
-			os_file_close(suspend_file);
-
 		exists = TRUE;
 		while (exists) {
 			os_thread_sleep(200000); /*0.2 sec*/
 			success = os_file_status(suspend_path, &exists, &type);
-			if (!success)
-				break;
+			/* success == FALSE if file exists, but stat() failed.
+			os_file_status() prints an error message in this case */
+			ut_a(success);
 		}
-		xtrabackup_suspend_at_end = FALSE; /* suspend is 1 time */
 	}
 
 	/* Reinit the datasink */
@@ -4724,6 +4741,19 @@
 	}
 	msg("\n");
 
+	if (!log_copying_succeed) {
+		msg("xtrabackup: Error: log_copying_thread failed.\n");
+		exit(EXIT_FAILURE);
+	}
+
+	/* Signal innobackupex that log copying has stopped and it may now
+	unlock tables, so we can possibly stream xtrabackup_logfile later
+	without holding the lock. */
+	if (xtrabackup_suspend_at_end &&
+	    !xb_create_suspend_file(suspend_path)) {
+		exit(EXIT_FAILURE);
+	}
+
 	if(!xtrabackup_incremental) {
 		strcpy(metadata_type, "full-backuped");
 		metadata_from_lsn = ut_dulint_zero;
@@ -4753,11 +4783,6 @@
 
 	}
 
-	if (!log_copying_succeed) {
-		msg("xtrabackup: Error: log_copying_thread failed.\n");
-		exit(EXIT_FAILURE);
-	}
-
 	/* Stream the transaction log from the temporary file */
 	if (!xtrabackup_log_only && xtrabackup_stream &&
 	    xtrabackup_stream_temp_logfile(dst_log_fd, ds_ctxt)) {