LSN logged when preparing a backup doesn't match the value of to_lsn

MySQL & MariaDB Percona XtraBackup
1

Hello,

I’m trying to restore an incremental backup made with xtrabackup following this doc: Prepare an incremental backup - Percona XtraBackup

I’m preparing the base backup with this command: $ xtrabackup --prepare --apply-log-only --target-dir=/data/backups/base

According to the doc, the LSN logged during the final shutdown should match the value of to_lsn from the backup, which is not case for me.

The expected LSN is 29430847. The final LSN logged is 29430857.

Here are the logs:

2025-03-11T20:36:04.935614-00:00 0 [Note] [MY-013883] [InnoDB] The latest found checkpoint is at lsn = 29430847 in redo log file ./#innodb_redo/#ib_redo0.
2025-03-11T20:36:04.935671-00:00 0 [Note] [MY-012560] [InnoDB] The log sequence number 29348668 in the system tablespace does not match the log sequence number 29430847 in the redo log files!
2025-03-11T20:36:04.935682-00:00 0 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2025-03-11T20:36:04.935690-00:00 0 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2025-03-11T20:36:04.935856-00:00 0 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 29430809, whereas checkpoint_lsn = 29430847 and start_lsn = 29430784
2025-03-11T20:36:04.935870-00:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 29430847
2025-03-11T20:36:04.955264-00:00 0 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2025-03-11T20:36:04.955838-00:00 0 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...
2025-03-11T20:36:04.955854-00:00 0 [Note] [MY-012535] [InnoDB] Apply batch completed!
2025-03-11T20:36:05.056153-00:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2025-03-11T20:36:05.056882-00:00 0 [Note] [MY-013795] [InnoDB] Encryption key is loaded for undo tablespace 'innodb_undo_001'.
2025-03-11T20:36:05.057011-00:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2025-03-11T20:36:05.057840-00:00 0 [Note] [MY-013795] [InnoDB] Encryption key is loaded for undo tablespace 'innodb_undo_002'.
2025-03-11T20:36:05.058595-00:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2025-03-11T20:36:05.058968-00:00 0 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 1806
2025-03-11T20:36:05.101596-00:00 0 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete
2025-03-11T20:36:05.101626-00:00 0 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 42 ms.
2025-03-11T20:36:05.101707-00:00 0 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2025-03-11T20:36:05.101799-00:00 0 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2025-03-11T20:36:05.136828-00:00 0 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2025-03-11T20:36:05.138725-00:00 0 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2025-03-11T20:36:05.145900-00:00 0 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2025-03-11T20:36:05.146148-00:00 0 [Note] [MY-012976] [InnoDB] 8.4.0 started; log sequence number 29430857
2025-03-11T20:36:05.146535-00:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
2025-03-11T20:36:05.147415-00:00 0 [Note] [MY-011825] [Xtrabackup] Completed loading of 2 tablespaces into cache in 0.00119559 seconds
2025-03-11T20:36:05.184280-00:00 0 [Note] [MY-011825] [Xtrabackup] Time taken to build dictionary: 0.0368314 seconds
2025-03-11T20:36:05.184896-00:00 0 [Note] [MY-011825] [Xtrabackup] starting shutdown with innodb_fast_shutdown = 1
2025-03-11T20:36:05.185344-00:00 0 [Note] [MY-012330] [InnoDB] FTS optimize thread exiting.
2025-03-11T20:36:06.184820-00:00 0 [Note] [MY-013072] [InnoDB] Starting shutdown...
2025-03-11T20:36:06.188377-00:00 0 [Note] [MY-013084] [InnoDB] Log background threads are being closed...
2025-03-11T20:36:06.206853-00:00 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 29430857
2025-03-11T20:36:06.211270-00:00 0 [Note] [MY-015019] [Server] MySQL Server: Plugins Shutdown - start.
2025-03-11T20:36:06.211289-00:00 0 [Note] [MY-015020] [Server] MySQL Server: Plugins Shutdown - end.
2025-03-11T20:36:06.211807-00:00 0 [Note] [MY-011825] [Xtrabackup] completed OK!

At 2025-03-11T20:36:05.146148-00:00, the mysql instance seems to be restarted. Is it expected?

From what I’ve read, restarting mysql will update the LSN. So, if the restart is expected, the LSN logged cannot match the original LSN from the backup (in this case, the doc might be wrong).

Am I missing something?

Thank you :slight_smile:

2

Hello @Jean-Luc_Derrien

It is not restarting MySQL; it is restarting the internal innodb engine contained inside PXB. “MySQL” is not involved at all with the prepare setups of PXB.

Good catch! I’ll see if a PXB engineer can verify this, and will get the docs updated.

3

Thank you for the clarification and the follow up :+1:

4

Hello @matthewb

I’m wondering if you get a chance a review this potential issue?
I’m still wondering if this is expected or not.

Thank you

5

Hey @Jean-Luc_Derrien,
I received a reply from any engineer. He says that ‘apply-log-only’ only processes the redo log. Because of this, the LSNs should always match. Can you check with some repeated attempts if the LSN is always off by 10?

6

Hello @matthewb

Sorry for the delay.

Yes, the LSN is always off by 10.

I made 3 full backups, with these commands:

xtrabackup --defaults-file=/tmp/mybck/my.cnf --backup --target-dir=/tmp/mybck/base
xtrabackup --defaults-file=/tmp/mybck/my.cnf --backup --target-dir=/tmp/mybck/base2
xtrabackup --defaults-file=/tmp/mybck/my.cnf --backup --target-dir=/tmp/mybck/base3

Note: I’m not doing any incremental backup.

The to_lsn value is off by 10 also at the backup level.

Here are the xtrabackup_checkpoints:

backup_type = full-backuped
from_lsn = 0
to_lsn = 229796909
last_lsn = 229796909
flushed_lsn = 229796909
redo_memory = 0
redo_frames = 0
--
backup_type = full-backuped
from_lsn = 0
to_lsn = 229796919
last_lsn = 229796919
flushed_lsn = 229796919
redo_memory = 0
redo_frames = 0
---
backup_type = full-backuped
from_lsn = 0
to_lsn = 229796929
last_lsn = 229796929
flushed_lsn = 229796929
redo_memory = 0
redo_frames = 0

Then restoring with these commands:

xtrabackup --prepare --apply-log-only --target-dir=/tmp/mybck/base
xtrabackup --prepare --apply-log-only --target-dir=/tmp/mybck/base2
xtrabackup --prepare --apply-log-only --target-dir=/tmp/mybck/base3

And here is the output:

2025-06-16T09:37:00.510346-00:00 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 229796919
2025-06-16T09:41:27.968416-00:00 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 229796929
2025-06-16T09:41:44.983280-00:00 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 229796939

Could it be related to the crash recovery process? As in my initial post, I have these logs:

(...)
2025-06-16T09:36:59.012920-00:00 0 [Note] [MY-012560] [InnoDB] The log sequence number 29385013 in the system tablespace does not match the log sequence number 229796909 in the redo log files!
2025-06-16T09:36:59.012932-00:00 0 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2025-06-16T09:36:59.012941-00:00 0 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2025-06-16T09:36:59.013101-00:00 0 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 229796909, whereas checkpoint_lsn = 229796909 and start_lsn = 229796864
2025-06-16T09:36:59.013115-00:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 229796909
(...)

Thanks

7

Hi @Jean-Luc_Derrien,
I suggest turning this post into a bug. Please open a JIRA and put all of your attempts into the comments so that our PXB engineers can look at this more closely.

8

Thank you,

For the follow up here is the issue: Jira