MDEV-39468 Mariabackup: redo log copier stalls and fails with misleading error message#5375
MDEV-39468 Mariabackup: redo log copier stalls and fails with misleading error message#5375Thirunarayanan wants to merge 1 commit into
Conversation
|
|
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request introduces a mechanism in mariabackup to poll InnoDB's durably flushed redo LSN from the running server and use it as a parse limit (max_parse_lsn) for the log copier. This prevents the copier from parsing volatile tail blocks that are still being rewritten, avoiding torn reads and mid-mtr drift. The feedback highlights two important issues in the log copying thread: first, a connection failure (limit_con being NULL) can cause max_parse_lsn to remain stuck and stall the copier, which should be mitigated by falling back to no limit (max_parse_lsn = 0); second, a potential 1-second delay can occur during backup completion if metadata_last_lsn is set to 1 while unlocked, which can be resolved by adding a check before the timed wait.
Important
The consumer version of Gemini Code Assist on GitHub is being sunset. Starting June 18, 2026, new organization installations will be blocked, and all code review activity will officially cease on July 17, 2026.
For more details on the timeline and next steps, please review the Help Documentation.
| if (final_target && final_target <= recv_sys.lsn) | ||
| break; |
There was a problem hiding this comment.
If metadata_last_lsn is set to 1 (the stop signal) while the thread is unlocked during get_log_flushed_lsn(), the thread will re-acquire the mutex, run xtrabackup_copy_logfile(false), and then reach the wait condition. Since final_target was evaluated as 0 before the unlock, the check final_target && final_target <= recv_sys.lsn will be false, causing the thread to call mysql_cond_timedwait and sleep for up to xtrabackup_log_copy_interval (default 1 second) before looping and finally breaking.
To avoid this unnecessary 1-second delay during backup completion, we should check if (metadata_last_lsn == 1) break; right before the wait condition.
if (final_target && final_target <= recv_sys.lsn)
break;
if (metadata_last_lsn == 1)
break;There was a problem hiding this comment.
Not a correctness issue anyway, and I understand metadata_last_lsn is set to 1 only on errors.
There was a problem hiding this comment.
Pull request overview
This PR addresses a mariabackup redo-log copier stall/drift issue (MDEV-39468) by fencing redo parsing to the server’s durably flushed LSN (via Innodb_lsn_flushed) and improving the resulting diagnostic messaging when the target LSN cannot be reached.
Changes:
- Add a redo-parse fence (
max_parse_lsn) and wrapper parsing logic to avoid parsing volatile/torn tail blocks while the server is still rewriting them. - Update
log_copying_thread()to refresh the parse limit via a dedicated client connection and suppress misleading “stall” retry logging when the parse fence is reached. - Add
get_log_flushed_lsn()helper and update the mariabackup test to expect the new messaging.
Reviewed changes
Copilot reviewed 5 out of 5 changed files in this pull request and generated 4 comments.
Show a summary per file
| File | Description |
|---|---|
| mysql-test/suite/mariabackup/innodb_redo_overwrite.test | Updates log-message assertion for the new “Try increasing…” output. |
| mysql-test/suite/mariabackup/innodb_redo_overwrite.result | Updates expected test output for the new log-message assertion. |
| extra/mariabackup/xtrabackup.cc | Implements parse fencing, updates retry/diagnostic behavior, and refreshes fence in the log copy thread. |
| extra/mariabackup/backup_mysql.h | Exposes get_log_flushed_lsn() declaration (adds <cstdint> include). |
| extra/mariabackup/backup_mysql.cc | Implements get_log_flushed_lsn() using SHOW STATUS LIKE 'Innodb_lsn_flushed'. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
iMineLink
left a comment
iMineLink
left a comment
There was a problem hiding this comment.
Thank you for the changes!
I understand thorough testing have already been performed and I have no further comments on correctness.
I have replied to AI's findings and have only a comments on connection error handling (maybe we abort early if limit_con fails to connect?), please check.
…ing 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;
Thirunarayanan
force-pushed
the
MDEV-39468
branch
from
5cfd81d to
d2a82bc
Compare
| 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; | ||
| } |
There was a problem hiding this comment.
I think this is relevant
| /* 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. */ |
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;