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 