From d2a82bc01790786bb441fabbfb52fee387ed0280 Mon Sep 17 00:00:00 2001 From: Thirunarayanan Balathandayuthapani Date: Wed, 15 Jul 2026 11:49:26 +0530 Subject: [PATCH] MDEV-39468 Mariabackup: redo log copier stalls and fails with misleading error message Problem: ======== During backup process, log copier thread stalls at lsn and fails with the misleading "Was only able to copy log from X to Y, not Z; try increasing innodb_log_file_size", even when the redo was intact and the log far from full. Problem is that copier advances recv_sys.lsn only on CRC-validated mtr, but it parses the redo at the server is concurrently writing. InnoDB rewrites the current partial write block repeatedly as mini-transaction fills it, so an mmap read (or) pread of a page being written can observe a torn/intermediate image of the tail block. If that tail block happens to parse as a longer, still valid crc valid mtr then recv_sys.lsn, recv_sys.offset gets advanced wrongly and points to middle of the mini-transaction. In that case, later parse return GOT_EOF always and copier thread never reaches target and fails Solution: ========= Poll the server's durably-flushed LSN (status var Innodb_lsn_flushed) and limit the redo log copier based on it. backup_log_parse(): parses one mtr and if it exceeds the limit rolls back recv_sys.lsn/offset and reports GOT_EOF; the copier re-parses those bytes on a later pass once the fence has advanced past them. Used on both the mmap and buffered paths. log_copying_thread(): opens its own connection (it runs concurrently with the main thread, which owns mysql_connection) and refreshes the max_limit for parsing of redo log in each pass. In the final backup phase (BACKUP STAGE BLOCK_COMMIT) it gates on the exact target max(metadata_last_lsn, metadata_to_lsn). so the last partial block is copied in full up to the target. The stall diagnostic / retry spin is suppressed on a reached_parse_limit wait so a normal "caught up, wait" is not misreported as drift. get_log_flushed_lsn(): Added to get log_flushed_lsn from SHOW STATUS outout; --- extra/mariabackup/backup_mysql.cc | 20 ++++ extra/mariabackup/backup_mysql.h | 3 + extra/mariabackup/xtrabackup.cc | 113 ++++++++++++++++-- .../mariabackup/innodb_redo_overwrite.result | 2 +- .../mariabackup/innodb_redo_overwrite.test | 2 +- 5 files changed, 128 insertions(+), 12 deletions(-) diff --git a/extra/mariabackup/backup_mysql.cc b/extra/mariabackup/backup_mysql.cc index 7fa02b1128c6d..0832045c10fea 100644 --- a/extra/mariabackup/backup_mysql.cc +++ b/extra/mariabackup/backup_mysql.cc @@ -346,6 +346,26 @@ read_mysql_one_value(MYSQL *mysql, const char *query) return read_mysql_one_value(mysql, query, 0/*offset*/, 1/*total columns*/); } +/** Poll InnoDB's durably flushed redo LSN from the running server. +Log copier uses this as its parse limit; it never accepts a redo log +record whose end exceeds this LSN +@param connection MariaDB client connection +@retval 0 on failure, lsn on success */ +uint64_t get_log_flushed_lsn(MYSQL *connection) noexcept +{ + char *lsn_str= nullptr; + mysql_variable status[] = {{"Innodb_lsn_flushed", &lsn_str}, + {NULL, NULL}}; + uint64_t lsn= 0; + read_mysql_variables(connection, + "SHOW STATUS LIKE 'Innodb_lsn_flushed'", + status, true); + if (lsn_str) + lsn= strtoull(lsn_str, nullptr, 10); + free_mysql_variables(status); + return lsn; +} + static bool diff --git a/extra/mariabackup/backup_mysql.h b/extra/mariabackup/backup_mysql.h index 55700dddf6d67..76f4bc666b3f8 100644 --- a/extra/mariabackup/backup_mysql.h +++ b/extra/mariabackup/backup_mysql.h @@ -2,6 +2,7 @@ #define XTRABACKUP_BACKUP_MYSQL_H #include +#include #include #include #include "datasink.h" @@ -97,4 +98,6 @@ bool write_slave_info(ds_ctxt *datasink, MYSQL *connection); ulonglong get_current_lsn(MYSQL *connection); + +uint64_t get_log_flushed_lsn(MYSQL *connection) noexcept; #endif diff --git a/extra/mariabackup/xtrabackup.cc b/extra/mariabackup/xtrabackup.cc index 0d4e2a65bf544..96e943b1a5ecf 100644 --- a/extra/mariabackup/xtrabackup.cc +++ b/extra/mariabackup/xtrabackup.cc @@ -205,7 +205,7 @@ struct xb_filter_entry_t{ /** whether log_copying_thread() is active; protected by recv_sys.mutex */ static bool log_copying_running; /** the log parsing function for --backup */ -static recv_sys_t::parser backup_log_parse; +static recv_sys_t::parser backup_log_parse_low; /** for --backup, target LSN to copy the log to; protected by recv_sys.mutex */ lsn_t metadata_to_lsn; @@ -3443,6 +3443,39 @@ static my_bool xtrabackup_copy_datafile(ds_ctxt *ds_data, return(FALSE); } +/* Maximum LSN the copier may parse up to, derived from the +server's durably-flushed redo LSN. The copier refuses to +accept a mini-transaction whose end exceeds this, so it never +parses the volatile tail block the server is still rewriting +(which mmap can read torn, leading to a mis-computed mtr +length and permanent mid-mtr drift). A pread() of the same +still-being-written tail block can likewise return a torn read +which can be observed on ext4, though not on XFS). +Read/written only under recv_sys.mutex. */ +static lsn_t max_parse_lsn; + +/* Set by backup_log_parse() when the last parse was +rejected because the mtr crossed max_parse_lsn. It means +"caught up, wait" condition, not a stall. */ +static bool reached_parse_limit; + +static recv_sys_t::parse_mtr_result backup_log_parse() +{ + const lsn_t limit_lsn= max_parse_lsn; + const lsn_t prev_lsn= recv_sys.lsn; + const size_t prev_offset= recv_sys.offset; + reached_parse_limit= false; + recv_sys_t::parse_mtr_result r= backup_log_parse_low(false); + if (r == recv_sys_t::OK && limit_lsn && recv_sys.lsn > limit_lsn) + { + recv_sys.lsn= prev_lsn; + recv_sys.offset= prev_offset; + reached_parse_limit= true; + return recv_sys_t::GOT_EOF; + } + return r; +} + static int xtrabackup_copy_mmap_snippet(ds_file_t *ds, const byte *start, const byte *end) { @@ -3468,7 +3501,7 @@ static bool xtrabackup_copy_mmap_logfile() const byte *start= &log_sys.buf[recv_sys.offset]; ut_d(recv_sys_t::parse_mtr_result r); - if ((ut_d(r=) backup_log_parse(false)) == recv_sys_t::OK) + if ((ut_d(r=) backup_log_parse()) == recv_sys_t::OK) { do { @@ -3486,7 +3519,7 @@ static bool xtrabackup_copy_mmap_logfile() start = seq + 1; } } - while ((ut_d(r=) backup_log_parse(false)) == recv_sys_t::OK); + while ((ut_d(r=) backup_log_parse()) == recv_sys_t::OK); if (xtrabackup_copy_mmap_snippet(dst_log_file, start, &log_sys.buf[recv_sys.offset])) @@ -3559,7 +3592,7 @@ static bool xtrabackup_copy_logfile(bool early_exit) if (log_sys.buf[recv_sys.offset] <= 1) break; - if (backup_log_parse(false) == recv_sys_t::OK) + if (backup_log_parse() == recv_sys_t::OK) { do { @@ -3569,7 +3602,7 @@ static bool xtrabackup_copy_logfile(bool early_exit) sequence_offset)); *seq= 1; } - while ((r= backup_log_parse(false)) == recv_sys_t::OK); + while ((r= backup_log_parse()) == recv_sys_t::OK); if (ds_write(dst_log_file, log_sys.buf + start_offset, recv_sys.offset - start_offset)) @@ -3599,6 +3632,9 @@ static bool xtrabackup_copy_logfile(bool early_exit) if (retry_count == 100) break; + if (reached_parse_limit) + break; + mysql_mutex_unlock(&recv_sys.mutex); if (!retry_count++) msg("Retrying read of log at LSN=" LSN_PF, recv_sys.lsn); @@ -3617,9 +3653,20 @@ static bool backup_wait_timeout(lsn_t lsn, lsn_t last_lsn) { if (last_lsn >= lsn) return true; + + const lsn_t checkpoint_lsn= log_sys.last_checkpoint_lsn.load(); + const lsn_t capacity= log_sys.file_size - log_sys.START_OFFSET; + const lsn_t needed= lsn - checkpoint_lsn; + msg("Was only able to copy log from " LSN_PF " to " LSN_PF - ", not " LSN_PF "; try increasing innodb_log_file_size", - log_sys.last_checkpoint_lsn.load(), last_lsn, lsn); + ", not " LSN_PF, checkpoint_lsn, last_lsn, lsn); + + if (needed <= capacity) + msg("mariabackup: The required redo still fits within the log " + "capacity, so it has not been overwritten; check whether the " + "server and backup configuration are the same."); + else + msg("mariabackup: Try increasing the innodb_log_file_size."); return false; } @@ -3674,16 +3721,56 @@ static bool backup_wait_for_lsn(lsn_t lsn) static void log_copying_thread() { my_thread_init(); + MYSQL *limit_con= xb_mysql_connect(); + if (!limit_con) + { + /* Without this connection we cannot poll the durably-flushed + LSN, so max_parse_lsn could never advance and the copier + would either stall or parse the volatile tail block. + Fail the copy gracefully and let the main thread report + it via backup_wait_timeout(). */ + msg("mariabackup: Error: cannot open a server connection for " + "the log copying thread; the backup will fail."); + mysql_mutex_lock(&recv_sys.mutex); + log_copying_running= false; + pthread_cond_broadcast(&scanned_lsn_cond); + mysql_mutex_unlock(&recv_sys.mutex); + my_thread_end(); + return; + } + mysql_mutex_lock(&recv_sys.mutex); - while (!xtrabackup_copy_logfile(false) && - (!metadata_last_lsn || metadata_last_lsn > recv_sys.lsn)) + for (;;) { + if (metadata_last_lsn == 1) + break; + /* Refresh the max_parse_lsn before each copy pass */ + const lsn_t final_target= metadata_last_lsn > metadata_to_lsn + ? metadata_last_lsn : metadata_to_lsn; + if (final_target) + max_parse_lsn= final_target; + else + { + mysql_mutex_unlock(&recv_sys.mutex); + lsn_t flushed= get_log_flushed_lsn(limit_con); + mysql_mutex_lock(&recv_sys.mutex); + if (flushed > log_sys.get_first_lsn()) + max_parse_lsn= flushed; + } + + if (xtrabackup_copy_logfile(false)) + break; + if (final_target && final_target <= recv_sys.lsn) + break; + timespec abstime; set_timespec_nsec(abstime, 1000000ULL * xtrabackup_log_copy_interval); mysql_cond_timedwait(&log_copying_stop, &recv_sys.mutex, &abstime); } log_copying_running= false; mysql_mutex_unlock(&recv_sys.mutex); + if (limit_con) + mysql_close(limit_con); my_thread_end(); } @@ -5614,9 +5701,15 @@ static bool xtrabackup_backup_func() /* copy log file by current position */ mysql_mutex_lock(&recv_sys.mutex); - backup_log_parse = recv_sys.get_backup_parser(); + backup_log_parse_low = recv_sys.get_backup_parser(); recv_sys.lsn = log_sys.last_checkpoint_lsn; + if (lsn_t flushed= get_log_flushed_lsn(mysql_connection)) + { + if (flushed > log_sys.get_first_lsn()) + max_parse_lsn= flushed; + } + const bool log_copy_failed = xtrabackup_copy_logfile(true); mysql_mutex_unlock(&recv_sys.mutex); diff --git a/mysql-test/suite/mariabackup/innodb_redo_overwrite.result b/mysql-test/suite/mariabackup/innodb_redo_overwrite.result index bab5d4331e07b..cbc7f44cab325 100644 --- a/mysql-test/suite/mariabackup/innodb_redo_overwrite.result +++ b/mysql-test/suite/mariabackup/innodb_redo_overwrite.result @@ -1,5 +1,5 @@ CREATE TABLE t ENGINE=INNODB SELECT seq%10 i FROM seq_0_to_204796; # xtrabackup backup -FOUND 1 /Was only able to copy log from \d+ to \d+, not \d+; try increasing innodb_log_file_size\b/ in backup.log +FOUND 1 /mariabackup: Try increasing the innodb_log_file_size./ in backup.log NOT FOUND /failed: redo log block checksum does not match/ in backup.log DROP TABLE t; diff --git a/mysql-test/suite/mariabackup/innodb_redo_overwrite.test b/mysql-test/suite/mariabackup/innodb_redo_overwrite.test index ab5993d232c4e..8c26acf4141ae 100644 --- a/mysql-test/suite/mariabackup/innodb_redo_overwrite.test +++ b/mysql-test/suite/mariabackup/innodb_redo_overwrite.test @@ -17,7 +17,7 @@ CREATE TABLE t ENGINE=INNODB SELECT seq%10 i FROM seq_0_to_204796; --exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir --dbug=+d,mariabackup_events > $backuplog --enable_result_log ---let SEARCH_PATTERN=Was only able to copy log from \\d+ to \\d+, not \\d+; try increasing innodb_log_file_size\\b +--let SEARCH_PATTERN=mariabackup: Try increasing the innodb_log_file_size. --let SEARCH_FILE=$backuplog --source include/search_pattern_in_file.inc --remove_file $backuplog