Restore percona xtrabacup with "log sequence number in the future"

MySQL & MariaDB Percona XtraBackup
1

I’m always using Percona Xtrabackup (percona-xtrabackup-80-8.0.33-28.1) to backup MySQL 8.0.27.
The backup command was as below:
xtrabackup --user=bakuser --password=‘xxx’ --backup --stream=xbstream --compress --target-dir=/backup/xtrbackup/ > $targetfile;

After that, I copied the backup file (xbstream file) and restored it at target slave machine. Restore command was as below:
xbstream -x -C xtrabackup_backupfiles/<$1
xtrabackup --decompress --parallel=6 --compress-threads=6
find ./xtrabackup_backupfiles/ -name ‘*.qp’ -type f -exec rm -rf {} ;
cd xtrabackup_backupfiles
mkdir -p ‘#innodb_redo’ ‘#innodb_temp’

After I restored successfully, I open the targeted instance, and did some query testing. I got some errors as below:
xxxx I/O related errors.

I checked mysql.log with errors as below:
2024-01-05T02:49:18.009264Z 0 [Warning] [MY-011068] [Server] The syntax ‘log_slave_updates’ is deprecated and will be removed in a future release. Please use log_replica_updates instead.
2024-01-05T02:49:18.009285Z 0 [Warning] [MY-011070] [Server] ‘Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it’ is deprecated and will be removed in a future release.
2024-01-05T02:49:18.011710Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 2417780
2024-01-05T02:49:18.036538Z 0 [Warning] [MY-010075] [Server] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 051cdb23-ab75-11ee-be6e-0050569ef18e.
2024-01-05T02:49:18.043796Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-01-05T02:49:18.792237Z 1 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_system’ Page [page id: space=0, page number=5] log sequence number 907936556002 is in the future! Current system log sequence number 907864015372.
2024-01-05T02:49:18.792276Z 1 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.
2024-01-05T02:49:18.795447Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=130] log sequence number 907938965493 is in the future!Current system log sequence number 907864015372.
2024-01-05T02:49:18.795485Z 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.

That’s the second time I faced this error. After that, I used logical backup with mysqldump to setup corrupted slave instances.

I used this backup/restore scripts to manage almost 80 mysql instances. I found if database backup file was more than 50G size, the restore script will be failed with some similar errors.

1 Like
2

Hi Wang,

We have a blogpost about this: How to move the InnoDB log sequence number (LSN) forward

Did you face this error twice on the same instance or on a different instance? I would suggest you check the server (from which you took the backup) for corruption

Then -even though it’s technically possible to use a newer PXB version to backup and older PXB version- you should try using the same PXB version as your MySQL instance. I.e if your MySQl server is 8.0.27 then use PXB 8.0.27 (or consider upgrading both to latest).
When restoring to MUST use the exact same version you used from the original instance

Regards

3

Hi CTutte,

Just now I used the same PXB version(percona-xtrabackup-80-8.0.27-19) to backup mysql database(8.0.27). After that, I used same PXB version and mysql database to restore at another box.
There’re no errors during restore.
Below are some details about restore comand:
xtrabackup --decompress --parallel=6 --compress-threads=6 >>./1.log
xtrabackup: recognized server arguments: --log_bin=mysql-bin.log --server-id=9163 --datadir=/data/mysqldata --innodb_buffer_pool_size=16G --innodb_log_file_size=128M --innodb_log_files_in_group=3 --innodb_log_buffer_size=8M
xtrabackup: recognized client arguments: --decompress=1 --parallel=6 --compress-threads=6
xtrabackup version 8.0.27-19 based on MySQL server 8.0.27 Linux (x86_64) (revision id: 50dbc8dadda)
240110 10:48:09 [03] decompressing ./xtrabackup_logfile.qp
…
240110 10:53:03 [02] decompressing ./mysql-bin.index.qp
240110 10:53:03 [02] decompressing ./xtrabackup_binlog_info.qp
240110 10:53:03 [02] decompressing ./ib_buffer_pool.qp
240110 10:53:03 [02] decompressing ./backup-my.cnf.qp
240110 10:53:03 [02] decompressing ./xtrabackup_info.qp
240110 10:53:03 [02] decompressing ./xtrabackup_tablespaces.qp
240110 11:06:54 completed OK!

After I opened this new recovered database, I got some errors as below:
2024-01-10T07:44:35.841938Z 0 [ERROR] [MY-012154] [InnoDB] Server exits.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
where mysqld died. If you see no messages after this, something went
terribly wrong…
stack_bottom = 0 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2040261]
/usr/sbin/mysqld(handle_fatal_signal+0x313) [0xf04a43]
/lib64/libpthread.so.0(+0x12cf0) [0x7f01e416ccf0]
/lib64/libc.so.6(gsignal+0x10f) [0x7f01e251bacf]
/lib64/libc.so.6(abort+0x127) [0x7f01e24eeea5]
/usr/sbin/mysqld() [0xc3e9d4]
/usr/sbin/mysqld() [0x244c036]
/usr/sbin/mysqld(Fil_shard::do_io(IORequest const&, bool, page_id_t const&, page_size_t const&, unsigned long, unsigned long, void*, void*)+0xdc1) [0x24636d1]
/usr/sbin/mysqld(fil_io(IORequest const&, bool, page_id_t const&, page_size_t const&, unsigned long, unsigned long, void*, void*)+0x6d) [0x246377d]
/usr/sbin/mysqld(buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, page_id_t const&, page_size_t const&, bool)+0x1b7) [0x2399707]
/usr/sbin/mysqld(buf_read_page(page_id_t const&, page_size_t const&)+0x4a) [0x2399d1a]
/usr/sbin/mysqld(Buf_fetch<Buf_fetch_normal>::read_page()+0x38) [0x2369298]
/usr/sbin/mysqld(Buf_fetch_normal::get(buf_block_t*&)+0x170) [0x2373500]
/usr/sbin/mysqld(Buf_fetch<Buf_fetch_normal>::single_page()+0x57) [0x23735e7]
/usr/sbin/mysqld(buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, Page_fetch, char const*, unsigned long, mtr_t*, bool)+0x1d6) [0x2375e06]
/usr/sbin/mysqld() [0x22f0bf7]
/usr/sbin/mysqld(trx_rseg_init_thread(void*, unsigned long)+0x501) [0x22f6c91]
/usr/sbin/mysqld(std::thread::_State_impl<std::thread::_Invoker<std::tuple<Detached_thread, void ()(void, unsigned long), void*, unsigned long> > >::_M_run()+0xc8) [0x22f04c8]
/lib64/libstdc++.so.6(+0xc2b13) [0x7f01e2eeeb13]
/lib64/libpthread.so.0(+0x81ca) [0x7f01e41621ca]
/lib64/libc.so.6(clone+0x43) [0x7f01e2506e73]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2024-01-10T07:44:38.094244Z 0 [Warning] [MY-011068] [Server] The syntax ‘log_slave_updates’ is deprecated and will be removed in a future release. Please use log_replica_updates instead.
2024-01-10T07:44:38.094265Z 0 [Warning] [MY-011070] [Server] ‘Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it’ is deprecated and will be removed in a future release.
2024-01-10T07:44:38.095482Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 993637
2024-01-10T07:44:38.104661Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-01-10T07:44:39.366067Z 1 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_system’ Page [page id: space=0, page number=5] log sequence number 973009735907 is in the future! Current system log sequence number 907864015372.
2024-01-10T07:44:39.366168Z 1 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to forcing-innodb-recovery.html for information about forcing recovery.

So how to fix this error?

4

Hi @wang.changmao and welcome to Percona community,

Can you confirm what’s the size of innodb_log_file_size? Are they large enough to hold your redo logs for the time backup runs?

Thanks,
K.

5

innodb_log_file_size is 128MB.
mysql> select @@innodb_log_file_size;
±-----------------------+
| @@innodb_log_file_size |
±-----------------------+
| 134217728 |
±-----------------------+
1 row in set (0.00 sec)

how to estimate whether or not it will hold my redo logs for the time backup runs?

Based on my understanding, PXB will copy the binary logs at the begin and end of backup. After that, it will apply those binary logs to restore database. How the PXB use redo logs for backup?

6

Hi @wang.changmao,

We have the documentation page very well explaining how xtrabackup works. I suggest you to go through that.
If you’re using PMM, you can check the redolog usage on “Innodb Details” dashboard as follows:

image
image1432×610 44.1 KB

You may see the PMM demo dashboard here.
There are some blogs about redo-log on MySQL 8 you might like to read:

Thanks,
K

7

Hi @kedarpercona ,
Last night, I resized the redo log size from 128M to 256M. I have three ib_logfiles.
I used below model to estimate the redo log size:
mysql> show status like ‘Innodb_os_log_written’;
±----------------------±-----------+
| Variable_name | Value |
±----------------------±-----------+
| Innodb_os_log_written | 3507742208 |
±----------------------±-----------+
1 row in set (0.00 sec)
mysql> status;

/usr/bin/mysql Ver 8.0.27 for Linux on x86_64 (MySQL Community Server - GPL)
…Uptime: 13 hours 3 min 37 sec
mysql> select 3507742208/13/1024/1024;
±------------------------+
| 3507742208/13/1024/1024 |
±------------------------+
| 257.326434795673 |
±------------------------+
1 row in set (0.00 sec)
Based on above calculation, this mysql instance generated 256M bytes logs per hour. So I resized redo log to 256M. Please correct me,if I’m wrong.

After that, I used new backup and then restore it.
Now I can open the restored database. However, there’re still errors in error logs as below:
2024-01-11T01:45:19.214371Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-01-11T01:45:20.593243Z 1 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_system’ Page [page id: space=0, page number=5] log sequence number 827793860524 is in the future! Current system log sequence number 197429952012.
2024-01-11T01:45:20.593314Z 1 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.
2024-01-11T01:45:20.600058Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=130] log sequence number 827793696518 is in the future!Current system log sequence number 197429952012.
2024-01-11T01:45:20.600159Z 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.
2024-01-11T01:45:20.600196Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=129] log sequence number 827793696475 is in the future!Current system log sequence number 197429952012.
2024-01-11T01:45:20.600248Z 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.
2024-01-11T01:45:20.600307Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=132] log sequence number 827793696604 is in the future!Current system log sequence number 197429952012.
2024-01-11T01:45:20.600414Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=131] log sequence number 827793696561 is in the future!Current system log sequence number 197429952012.

And the second issue, during this restore, I losted one big size table (256G).
From the log of restore command(xbstream -x -C xtrabackup_backupfiles/<./xtrabak_hthxdata_20240101003002.xbstream), I can find the losted table message.
I’m not sure why.
backupground: On master PKB and mysql are both 8.0.27. On slave, they’re same too.

8

@kedarpercona ，

Just now I reinstalled PKB 8.0.31 on master and slave box. However, the mysql version is still 8.0.27.
Now I can open the restored mysql instance on salve box. I can find the missed table during last backup and restore test (PKB 8.0.27 and mysql 8.0.27).

There’re still errors as last time:
2024-01-11T06:06:41.816252Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27) starting as process 1090344
2024-01-11T06:06:41.825169Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-01-11T06:06:43.106296Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=132] log sequence number 976782637851 is in the future!Current system log sequence number 973753557777.
2024-01-11T06:06:43.106456Z 0 [ERROR] [MY-011971] [InnoDB] Tablespace ‘innodb_undo_002’ Page [page id: space=4294967278, page number=131] log sequence number 976790671531 is in the future!Current system log sequence number 973753557777.

I don’t know why current LSN is 973753557777 in restored database?
When I backuped the master database, the beginning LSN is 976782343794.
Some details are as below:
[root@ysp-db01 ~]# bash ./xtrbackup.sh
2024-01-11T10:20:15.109815+08:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --log_bin=mysql-bin.log --server-id=93 --datadir=/data/mysqldata --innodb_buffer_pool_size=7G --innodb_log_file_size=256M --innodb_log_files_in_group=3 --innodb_log_buffer_size=8M
2024-01-11T10:20:15.109986+08:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --user=bakuser --password=* --backup=1 --stream=xbstream --compress --target-dir=/backup/xtrbackup/
xtrabackup version 8.0.31-24 based on MySQL server 8.0.31 Linux (x86_64) (revision id: f0754edb)
Can’t locate English.pm in @INC (you may need to install the English module) (@INC contains: /usr/local/lib64/perl5/5.32 /usr/local/share/perl5/5.32 /usr/lib64/perl5/vendor_perl /usr/share/perl5/vendor_perl /usr/lib64/perl5 /usr/share/perl5) at - line 3.
BEGIN failed–compilation aborted at - line 3.
2024-01-11T10:20:15.184119+08:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: bakuser, password: set, port: not set, socket: not set
2024-01-11T10:20:15.325899+08:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.27
2024-01-11T10:20:15.390138+08:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK INSTANCE FOR BACKUP …
2024-01-11T10:20:15.427937+08:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2024-01-11T10:20:15.428000+08:00 0 [Note] [MY-011825] [Xtrabackup] cd to /data/mysqldata
2024-01-11T10:20:15.428018+08:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 0, set to 1024
2024-01-11T10:20:15.428061+08:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2024-01-11T10:20:15.428076+08:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2024-01-11T10:20:15.428084+08:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2024-01-11T10:20:15.428118+08:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2024-01-11T10:20:15.428129+08:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 3
2024-01-11T10:20:15.428137+08:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 268435456
2024-01-11T10:20:15.468028+08:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2024-01-11T10:20:15.577140+08:00 0 [Note] [MY-012529] [InnoDB] Redo log format is v4. The redo log was created before MySQL 8.0.30.
…
2024-01-11T10:20:15.689749+08:00 0 [Note] [MY-011825] [Xtrabackup] Starting to parse redo log at lsn = 976782155328
2024-01-11T10:20:15.691281+08:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (976782343794)
2024-01-11T10:20:16.063777+08:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2024-01-11T10:20:16.063854+08:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2024-01-11T10:20:16.063871+08:00 0 [Note] [MY-012204] [InnoDB] Scanning ‘./’
2024-01-11T10:20:16.065251+08:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2024-01-11T10:20:16.082798+08:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
2024-01-11T10:20:16.691482+08:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (976782343794)
2024-01-11T10:20:16.740498+08:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘./undo_001’.
2024-01-11T10:20:16.741958+08:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘./undo_002’.
2024-01-11T10:20:16.748444+08:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
…

9

Hi,

I’d keep the version same as was suggested earlier. Let’s do this:

  • set redolog size to 1G.
  • ensure both source and destination are at same versions (PS and PXC both)
  • perform the restore

Provide with both backup log and restore log.
Thanks,
K

10

@kedarpercona ,

After resize the redolog to 1G on slave database, I restarted the slave database with new parameter and then did backup and restore.
Before, I used master database to do backup and restore.
PKB version: 8.0.31 (both source and target)
DB version: 8.0.27 (both source and target)
Please check attatched file for details.
backup and restore with xtrabackup.log (272.2 KB)

11

hey @wang.changmao

Am I seeing that you’re missing the prepare step after decompress?
xtrabackup --prepare --target-dir=/data/secondData/

Can you please prepare backup before starting mysql?

Thanks,
K

12

I did NOT prepare backup before staring mysql. After I tried it, now the database can be open without any errors.
So there’re two questions about this:

  1. when or which version of xtrabackup do we need prepare backup before starting mysql?
    as you know, some databases can be opened normally without prepare backup

  2. about the parameter (innodb_log_file_size) of xtrabackup? Do I need modify this parameter in my.cnf and then restart mysqld service, or just modify the parameter （–innodb-log-file-size=） of xtrabackup command？

13

hmmm! so that’s a standard process - you must prepare a backup before starting database. I had shared a link earlier, here’s an excerpt:

During the prepare phase, Percona XtraBackup performs crash recovery against the copied data files, using the copied transaction log file. After this is done, the database is ready to restore and use.

I will strongly suggest you to read How Percona XtraBackup Works - Percona XtraBackup

About your questions:

  1. when or which version of xtrabackup do we need prepare backup before starting mysql?
    as you know, some databases can be opened normally without prepare backup
  • I am not sure what do you mean by “some databases can be opened normally without prepare backup” but a “prepare” step is important while using xtrabackup.
  • Probably you might be talking about xtrabackup of an idle database but still…
  • for all versions, always prepare your backup.
  • use identical versions
  1. about the parameter (innodb_log_file_size) of xtrabackup? Do I need modify this parameter in my.cnf and then restart mysqld service, or just modify the parameter （–innodb-log-file-size=） of xtrabackup command？
  • This parameter is of redolog size, which is MySQL’s configuration option. You donot need to adjust that parameter in xtrabackup.

Thanks,
K

14

@kedarpercona ,

Ok that fixed my questions.
Thanks a lot.

1 Like