Xtrabackup 8.0.31 reports Database page corruption with fresh mysql-community 8.0.31 database

MySQL & MariaDB Percona XtraBackup
1

Hi,

We are in the process of moving from MySQL 5.7 to MySQL 8 and have run into an issue with xtrabackup - it complains about page corruptions when copying ibdata1.

The database is on a test machine and was initialized using mysqld and then databases & tables created using mysqldump from another test MySQL 8 database with no data. At this point xtrabackup successfully created a backup.

I then loaded a small amount of data into some of the databases, again using mysqldump. After the data load, xtrabackup failed to create a backup when trying to copy ibdata1.

MySQL is working without errors, adding more data & querying hasn’t showed up any issues or resolved xtrabackups failure to copy ibdata1.

Any suggestions on what to try would be greatly appreciated.

System Setup:
Debian Buster 10.13
percona-xtrabackup-80:
Installed: 8.0.31-24-1.buster
Candidate: 8.0.32-26-1.buster
mysql-community-server:
Installed: 8.0.31-1debian10
Candidate: 8.0.33-1debian10

Command used:
sudo -u mysql xtrabackup --defaults-group-suffix=1 --backup --user=admin --password=* --target-dir=/srv/mysql_backups/for_mysqld2.bak

xrtabackup output:
2023-05-09T09:17:19.387497+10:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/var/lib/mysql/notused --tmpdir=/var/lib/mysql/tmp/notused --innodb_file_per_table=1 --innodb_log_buffer_size=16M --innodb_log_file_size=16M --server-id=549358661 --datadir=/var/lib/mysql/tirtlnet --tmpdir=/var/lib/mysql/tmp/tirtlnet --log_bin=/home/mysql/tirtlnet/binlog/mysql-bin.log --innodb_undo_directory=/var/lib/mysql/undo/tirtlnet --innodb_log_file_size=512M --innodb_io_capacity=6000 --innodb_buffer_pool_size=256M
2023-05-09T09:17:19.387874+10:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --port=3306 --socket=/var/run/mysqld/mysqld.sock --backup=1 --user=admin --password=* --target-dir=/srv/mysql_backups/for_mysqld2.bak
xtrabackup version 8.0.31-24 based on MySQL server 8.0.31 Linux (x86_64) (revision id: f0754edb)
230509 09:17:19 version_check Connecting to MySQL server with DSN ‘dbi:mysql:;mysql_read_default_group=xtrabackup;port=3306;mysql_socket=/var/run/mysqld/mysqld.sock’ as ‘admin’ (using password: YES).
230509 09:17:19 version_check Connected to MySQL server
230509 09:17:19 version_check Executing a version check against the server…
230509 09:17:19 version_check Done.
2023-05-09T09:17:19.449524+10:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: admin, password: set, port: 3306, socket: /var/run/mysqld/mysqld.sock
2023-05-09T09:17:19.452692+10:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.31
2023-05-09T09:17:19.454722+10:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK INSTANCE FOR BACKUP …
2023-05-09T09:17:19.456673+10:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2023-05-09T09:17:19.456704+10:00 0 [Note] [MY-011825] [Xtrabackup] cd to /var/lib/mysql/tirtlnet
2023-05-09T09:17:19.456723+10:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 0, set to 1024
2023-05-09T09:17:19.456751+10:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2023-05-09T09:17:19.456760+10:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2023-05-09T09:17:19.456763+10:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2023-05-09T09:17:19.456780+10:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2023-05-09T09:17:19.456787+10:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2023-05-09T09:17:19.456793+10:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 536870912
2023-05-09T09:17:19.457887+10:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2023-05-09T09:17:19.524080+10:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: admin, password: set, port: 3306, socket: /var/run/mysqld/mysqld.sock
2023-05-09T09:17:19.526846+10:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2023-05-09T09:17:19.636272+10:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (159102699)
2023-05-09T09:17:19.849323+10:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2023-05-09T09:17:19.849613+10:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2023-05-09T09:17:19.850198+10:00 0 [Note] [MY-012204] [InnoDB] Scanning ‘./’
2023-05-09T09:17:19.854945+10:00 0 [Note] [MY-012204] [InnoDB] Scanning ‘/var/lib/mysql/undo/tirtlnet/’
2023-05-09T09:17:19.855034+10:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2023-05-09T09:17:19.855140+10:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 490 for vic@002droads/wim_axle, old maximum was 0
2023-05-09T09:17:19.863771+10:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘/var/lib/mysql/undo/tirtlnet/undo_001’.
2023-05-09T09:17:19.864218+10:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘/var/lib/mysql/undo/tirtlnet/undo_002’.
2023-05-09T09:17:19.864718+10:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2023-05-09T09:17:19.864999+10:00 2 [Note] [MY-011825] [Xtrabackup] Copying ./tirtlnet/orientation.ibd to /srv/mysql_backups/for_mysqld2.bak/tirtlnet/orientation.ibd
2023-05-09T09:17:19.865252+10:00 2 [Note] [MY-011825] [Xtrabackup] Done: Copying ./tirtlnet/orientation.ibd to /srv/mysql_backups/for_mysqld2.bak/tirtlnet/orientation.ibd
2023-05-09T09:17:19.870660+10:00 2 [Note] [MY-011825] [Xtrabackup] Copying ./vic@002ddoj/voi_site.ibd to /srv/mysql_backups/for_mysqld2.bak/vic@002ddoj/voi_site.ibd
2023-05-09T09:17:19.871534+10:00 2 [Note] [MY-011825] [Xtrabackup] Done: Copying ./vic@002ddoj/voi_site.ibd to /srv/mysql_backups/for_mysqld2.bak/vic@002ddoj/voi_site.ibd
2023-05-09T09:17:19.873837+10:00 2 [Note] [MY-011825] [Xtrabackup] Copying ./ibdata1 to /srv/mysql_backups/for_mysqld2.bak/ibdata1
2023-05-09T09:17:19.887136+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:19.993844+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.102886+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.212189+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.321017+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.429678+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.538434+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.636696+10:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (159102699)
2023-05-09T09:17:20.647886+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.756374+10:00 2 [Note] [MY-011825] [Xtrabackup] Database page corruption detected at page 256, retrying…
2023-05-09T09:17:20.864979+10:00 2 [ERROR] [MY-011825] [Xtrabackup] failed to read page after 10 retries. File ./ibdata1 seems to be corrupted.
2023-05-09T09:17:20.875691+10:00 2 [ERROR] [MY-011825] [Xtrabackup] xtrabackup_copy_datafile() failed
2023-05-09T09:17:20.875802+10:00 2 [ERROR] [MY-011825] [Xtrabackup] failed to copy datafile ./ibdata1
2023-05-09T09:17:21.637187+10:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (159102699)

I have tried running innochecksum as suggested in other forums posts:

sudo -u mysql innochecksum ibdata1
Fail: page 256 invalid
Exceeded the maximum allowed checksum mismatch count::0

2

Hi @murray.atkinson .

Based on the output of innochecksum this is clearly a data corruption. Xtrabackup validates page checksums while it’s copying the data to avoid corrupted backups.

Track, where the corruption has happened in the first place, is rather a difficult task. Since this is a test I would advise you to start over the process.

3

Hi Marcelo,

thanks for your quick reply. This was my 2nd attempt. It’s curious that MySQL doesn’t report any errors but xtrabackup does.

I’ve since tried upgrading mysql & xtrabackup to 8.0.32 on the server. MySQL upgraded without issue and I can still make use of the server. without issues.
xtrabackup still reports the same page corruption error with ibdata1.

I will try a clean mysql database with 8.0.32 and see what happens.

Thanks,

Murray.

4

@murray.atkinson,
InnoDB only checks pages when they are loaded into memory (ie: SELECT). It is perfectly possible for MySQL/InnoDB to not report any corruption errors if those pages are never accessed.
This is different from xtrabackup which must read every single page in order to take a backup and therefor looks at every checksum.
In theory, if you created a logical backup using mysqldump or MyDumper, you would see page corruption messages in your mysql log since both tools access every page during the dump process.

5

Hi Matthew,

thanks for your clarification about MySQL’s behavior.

I am trying to track down which step in our initialisation process for setting up new MySQL servers is producing this corruption.

I currently suspect it happens after a reboot and running of some of our initilialisation steps for our multi_mysql setup.

I have tried creating a new empty MySQL server which PXB successfully backs up. Then shudown MySQL, shutdown the VirtualBox VM, take a snapshot, start the VM which starts MySQL and then PXB reports a corrupted ibdata1 file.

Interestingly, running mysqldump --all-databases on the MySQL server succeeds without any errors.

Anyway, I will continue to great a minimal system & track down what event it producing this ibdata1 file corruption.

Again, thank you for you comments.

Murray

6

I have confirmed that my issue is somehow related to rebooting my VirtualBox VM. With MySQL shutdown (no mysqld processes running). Taking the md5sum of ibdata1 & mysql.ibd then shutdown -h 0 of the VM, then starting the VM without MySQL starting the md5sums of the ibdata1 & mysql.ibd have changed but the mtime of the files havn’t changed.

Something very strange happening, so more investigation required.

Again, thanks for you advice.

Murray.