MDEV-16496 Mariabackup: Implement --verbose option to instrument Inno…

…DB log apply

srv_print_verbose_log: Introduce the value 2 to refer to
mariabackup --verbose.

recv_recover_page(), recv_parse_log_recs(): Add output for
mariabackup --verbose.

extra/mariabackup/xtrabackup.cc

@@ -4,7 +4,7 @@ MariaBackup: hot backup tool for InnoDB
 Originally Created 3/3/2009 Yasufumi Kinoshita
 Written by Alexey Kopytov, Aleksandr Kuzminsky, Stewart Smith, Vadim Tkachenko,
 Yasufumi Kinoshita, Ignacio Nin and Baron Schwartz.
-(c) 2017, MariaDB Corporation.
+(c) 2017, 2018, MariaDB Corporation.
 Portions written by Marko Mäkelä.
 
 This program is free software; you can redistribute it and/or modify
@@ -109,6 +109,7 @@ int sys_var_init();
 char xtrabackup_real_target_dir[FN_REFLEN] = "./xtrabackup_backupfiles/";
 char *xtrabackup_target_dir= xtrabackup_real_target_dir;
 static my_bool xtrabackup_version;
+static my_bool verbose;
 my_bool xtrabackup_backup;
 my_bool xtrabackup_prepare;
 my_bool xtrabackup_copy_back;
@@ -696,6 +697,9 @@ enum options_xtrabackup
 
 struct my_option xb_client_options[] =
 {
+  {"verbose", 'V', "display verbose output",
+   (G_PTR*) &verbose, (G_PTR*) &verbose, 0, GET_BOOL, NO_ARG,
+   FALSE, 0, 0, 0, 0, 0},
   {"version", 'v', "print xtrabackup version information",
    (G_PTR *) &xtrabackup_version, (G_PTR *) &xtrabackup_version, 0, GET_BOOL,
    NO_ARG, 0, 0, 0, 0, 0, 0},
@@ -1756,7 +1760,7 @@ innodb_init_param(void)
 	srv_max_n_open_files = (ulint) innobase_open_files;
 	srv_innodb_status = (ibool) innobase_create_status_file;
 
-	srv_print_verbose_log = 1;
+	srv_print_verbose_log = verbose ? 2 : 1;
 
 	/* Store the default charset-collation number of this MySQL
 	installation */
@@ -3730,6 +3734,7 @@ static bool xtrabackup_backup_low()
 
 	if (metadata_to_lsn && xtrabackup_copy_logfile(true)) {
 		ds_close(dst_log_file);
+		dst_log_file = NULL;
 		return false;
 	}
 

mysql-test/suite/mariabackup/apply-log-only-incr.test

@@ -36,15 +36,15 @@ connection default;
 
 --disable_result_log
 exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --ftwrl-wait-timeout=5 --ftwrl-wait-threshold=300 --ftwrl-wait-query-type=all --target-dir=$incremental_dir --incremental-basedir=$basedir ;
-exec $XTRABACKUP --prepare --apply-log-only --target-dir=$basedir ;
+exec $XTRABACKUP --prepare --verbose --apply-log-only --target-dir=$basedir ;
 --enable_result_log
 
 let SEARCH_FILE=$MYSQLTEST_VARDIR/log/current_test;
 --let SEARCH_PATTERN= Rolled back recovered transaction
 --source include/search_pattern_in_file.inc
 --echo # expect NOT FOUND
 
-exec $XTRABACKUP --prepare --apply-log-only --target-dir=$basedir --incremental-dir=$incremental_dir ;
+exec $XTRABACKUP --prepare --verbose --apply-log-only --target-dir=$basedir --incremental-dir=$incremental_dir ;
 
 --source include/search_pattern_in_file.inc
 --echo # expect NOT FOUND

mysql-test/suite/mariabackup/mdev-14447.test

@@ -18,8 +18,8 @@ exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --target-dir
 
 --disable_result_log
 echo # Prepare full backup, apply incremental one;
-exec $XTRABACKUP --prepare --apply-log-only --target-dir=$basedir;
-exec $XTRABACKUP --prepare --apply-log-only --target-dir=$basedir --incremental-dir=$incremental_dir ;
+exec $XTRABACKUP --prepare --verbose --apply-log-only --target-dir=$basedir;
+exec $XTRABACKUP --prepare --verbose --apply-log-only --target-dir=$basedir --incremental-dir=$incremental_dir ;
 
 echo # Restore and check results;
 let $targetdir=$basedir;

storage/innobase/log/log0recv.cc

@@ -1772,6 +1772,11 @@ recv_recover_page(bool just_read_in, buf_block_t* block)
 
 	ut_ad(recv_needed_recovery);
 
+	if (UNIV_UNLIKELY(srv_print_verbose_log == 2)) {
+		fprintf(stderr, "Applying log to page %u:%u\n",
+			recv_addr->space, recv_addr->page_no);
+	}
+
 	DBUG_PRINT("ib_log",
 		   ("Applying log to page %u:%u",
 		    recv_addr->space, recv_addr->page_no));
@@ -1872,6 +1877,13 @@ recv_recover_page(bool just_read_in, buf_block_t* block)
 				start_lsn = recv->start_lsn;
 			}
 
+			if (UNIV_UNLIKELY(srv_print_verbose_log == 2)) {
+				fprintf(stderr, "apply " LSN_PF ":"
+					" %d len " ULINTPF " page %u:%u\n",
+					recv->start_lsn, recv->type, recv->len,
+					recv_addr->space, recv_addr->page_no);
+			}
+
 			DBUG_PRINT("ib_log",
 				   ("apply " LSN_PF ":"
 				    " %s len " ULINTPF " page %u:%u",
@@ -2422,6 +2434,16 @@ bool recv_parse_log_recs(lsn_t checkpoint_lsn, store_t store, bool apply)
 #endif
 			lsn = mach_read_from_8(ptr + 1);
 
+			if (UNIV_UNLIKELY(srv_print_verbose_log == 2)) {
+				fprintf(stderr,
+					"MLOG_CHECKPOINT(" LSN_PF ") %s at "
+					LSN_PF "\n", lsn,
+					lsn != checkpoint_lsn ? "ignored"
+					: recv_sys->mlog_checkpoint_lsn
+					? "reread" : "read",
+					recv_sys->recovered_lsn);
+			}
+
 			DBUG_PRINT("ib_log",
 				   ("MLOG_CHECKPOINT(" LSN_PF ") %s at "
 				    LSN_PF,