Hi,
My Xtrabackup is failing after a few hours, and I don’t understand why. The script was working previously, but it seems to be crashing randomly (about 3/4 of the times) since I implemented MySQL replication. I’m doing the backup on the master server.
The error is:
2023-04-22T07:49:18.972506-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/users.ibd
2023-04-22T07:49:18.973212-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/users.ibd
2023-04-22T07:49:19.632497-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_1.ibd
2023-04-22T07:52:50.183322-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_1.ibd
2023-04-22T07:52:50.542174-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_2.ibd
2023-04-22T07:52:50.542852-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_2.ibd
2023-04-22T07:52:51.002925-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_3.ibd
2023-04-22T07:52:51.003487-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_3.ibd
2023-04-22T07:52:51.417160-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_4.ibd
2023-04-22T07:52:51.418115-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_4.ibd
2023-04-22T07:52:51.727882-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_5.ibd
2023-04-22T07:52:51.730003-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_5.ibd
2023-04-22T07:52:52.066593-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_6.ibd
2023-04-22T07:52:52.067192-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/fts_0000000000000508_00000000000002a1_index_6.ibd
2023-04-22T07:52:52.441710-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./mysql.ibd
2023-04-22T07:52:55.090708-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./mysql.ibd
2023-04-22T07:52:55.596008-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./undo_002
2023-04-22T07:53:42.241119-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./undo_002
2023-04-22T07:53:42.668876-00:00 3 [Note] [MY-011825] [Xtrabackup] Streaming ./undo_001
2023-04-22T07:53:45.016203-00:00 3 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./undo_001
2023-04-22T08:08:17.312105-00:00 2 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics_old/abc_import.ibd
2023-04-22T08:11:48.062722-00:00 6 [Note] [MY-011825] [Xtrabackup] Done: Streaming ./altics/websites.ibd
2023-04-22T08:58:12.257839-00:00 1 [ERROR] [MY-012894] [InnoDB] Unable to open './#innodb_redo/#ib_redo18131' (error: 1504).
2023-04-22T08:58:12.261142-00:00 1 [ERROR] [MY-011825] [Xtrabackup] read_logfile() failed.
2023-04-22T08:58:12.845628-00:00 0 [ERROR] [MY-011825] [Xtrabackup] log copying failed.
Here is the command that is used to generate the backup:
xtrabackup --defaults-extra-file=/root/.my.cnf --backup --parallel=5 --stream=xbstream | pigz | gpg --trust-model always -e -r “My Name” | aws s3 cp --expected-size=$((1024*1024*1024 * 1000)) --cli-connect-timeout=3600 --cli-read-timeout=3600 - s3://bucket/db/$BACKUP_DATE.xbstream.gz.gpg > /home/forge/sync.log
For reference, here are some informations:
root@server:~# mysql -V
mysql Ver 8.0.30 for Linux on x86_64 (MySQL Community Server - GPL)
root@server:~# xtrabackup --version
2023-04-22T10:34:48.623486-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/home/forge/data/mysql-data --tmpdir=/home/forge/data/mysql-tmp --server-id=1 --log_bin=/home/forge/data/mysql-data/mysql-bin --innodb_data_home_dir=/home/forge/data/mysql-data --innodb_log_file_size=3G --innodb_log_files_in_group=4 --innodb_buffer_pool_size=42G --innodb_read_io_threads=64 --innodb_write_io_threads=64 --open_files_limit=8192
xtrabackup version 8.0.32-25 based on MySQL server 8.0.32 Linux (x86_64) (revision id: 14f007fb)
Do you have any insight ?
Thanks a lot !
I’ve found this in the doc:
Percona XtraBackup 8.0.30-23 adds --register-redo-log-consumer parameter. The --register-redo-log-consumer parameter is disabled by default. When enabled, this parameter lets Percona XtraBackup register as a redo log consumer at the start of the backup. The server does not remove a redo log that Percona XtraBackup (the consumer) has not yet copied. The consumer reads the redo log and manually advances the log sequence number (LSN). The server blocks the writes during the process. Based on the redo log consumption, the server determines when it can purge the log.
here: https://docs.percona.com/percona-xtrabackup/8.0/how_xtrabackup_works.html
I will try it and let you know if the problem is solved.
It didn’t work:
2023-04-22T20:09:49.080871-00:00 7 [Note] [MY-011825] [Xtrabackup] Streaming mysql/general_log_972.sdi to <STDOUT>
2023-04-22T20:09:49.080883-00:00 8 [Note] [MY-011825] [Xtrabackup] Done: Streaming performance_schema/socket_summary_b_908.sdi to <STDOUT>
2023-04-22T20:09:49.081046-00:00 7 [Note] [MY-011825] [Xtrabackup] Done: Streaming mysql/general_log_972.sdi to <STDOUT>
2023-04-22T20:09:49.081615-00:00 10 [Note] [MY-011825] [Xtrabackup] Streaming mysql/general_log.CSM to <STDOUT>
2023-04-22T20:09:49.081788-00:00 9 [Note] [MY-011825] [Xtrabackup] Streaming mysql/slow_log.CSV to <STDOUT>
2023-04-22T20:09:49.081817-00:00 9 [Note] [MY-011825] [Xtrabackup] Done: Streaming mysql/slow_log.CSV to <STDOUT>
2023-04-22T20:09:49.081834-00:00 11 [Note] [MY-011825] [Xtrabackup] Streaming mysql/slow_log.CSM to <STDOUT>
2023-04-22T20:09:49.081850-00:00 8 [Note] [MY-011825] [Xtrabackup] Streaming mysql/slow_log_974.sdi to <STDOUT>
2023-04-22T20:09:49.081853-00:00 10 [Note] [MY-011825] [Xtrabackup] Done: Streaming mysql/general_log.CSM to <STDOUT>
2023-04-22T20:09:49.082019-00:00 11 [Note] [MY-011825] [Xtrabackup] Done: Streaming mysql/slow_log.CSM to <STDOUT>
2023-04-22T20:09:49.082028-00:00 8 [Note] [MY-011825] [Xtrabackup] Done: Streaming mysql/slow_log_974.sdi to <STDOUT>
2023-04-22T20:09:49.150480-00:00 0 [Note] [MY-011825] [Xtrabackup] Finished backing up non-InnoDB tables and files
2023-04-22T20:09:49.150522-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
2023-04-22T20:10:06.140096-00:00 0 [Note] [MY-011825] [Xtrabackup] Selecting LSN and binary log position from p_s.log_status
2023-04-22T20:10:06.195741-00:00 0 [Note] [MY-011825] [Xtrabackup] Streaming /home/forge/data/mysql-data/mysql-bin.001868 to <STDOUT> up to position 21310
2023-04-22T20:10:06.195810-00:00 0 [Note] [MY-011825] [Xtrabackup] Done: Streaming /home/forge/data/mysql-data/mysql-bin.001868 to <STDOUT>
2023-04-22T20:10:06.195946-00:00 0 [Note] [MY-011825] [Xtrabackup] Streaming <STDOUT>
2023-04-22T20:10:06.195964-00:00 0 [Note] [MY-011825] [Xtrabackup] Done: Streaming file <STDOUT>
2023-04-22T20:10:06.218565-00:00 0 [Note] [MY-011825] [Xtrabackup] Streaming <STDOUT>
2023-04-22T20:10:06.218610-00:00 0 [Note] [MY-011825] [Xtrabackup] Done: Streaming file <STDOUT>
2023-04-22T20:10:06.218644-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
2023-04-22T20:10:06.241097-00:00 0 [Note] [MY-011825] [Xtrabackup] The latest check point (for incremental): '21429372624635'
2023-04-22T20:10:06.241141-00:00 0 [Note] [MY-011825] [Xtrabackup] Stopping log copying thread at LSN 21435121924755
2023-04-22T21:04:38.375485-00:00 1 [ERROR] [MY-012894] [InnoDB] Unable to open './#innodb_redo/#ib_redo18181' (error: 1504).
2023-04-22T21:04:38.375534-00:00 1 [ERROR] [MY-011825] [Xtrabackup] read_logfile() failed.
2023-04-22T21:04:38.376303-00:00 0 [ERROR] [MY-011825] [Xtrabackup] last checkpoint LSN (21429372624635) is larger than last copied LSN (21372158273024).
2023-04-22T21:04:38.376331-00:00 0 [ERROR] [MY-011825] [Xtrabackup] Error stopping copy thread at LSN 21435121924755
Greetings Julienarcin,
Welcome to Percona Community.
You might be stung by this bug and it is fixed in XtraBackup 8.0.32-26.
Can you upgrade to latest Xtrabackup and try again? Also backup on master is not a good idea, let’s think about moving that to replica.
Good luck,
K.
3 Likes
Hello Julienarcin,
I would try increasing the redo log size, as I believe it might be related to having a small redo log that is not able to keep all the records requested by xtrabackup. Given that you are on MySQL 8.0.30, you can take advantage of parameter innodb_redo_log_capacity. This parameter is dynamic, so you don’t need to restart your server to change it. Please verify the current size of your redo log and try to increase it. If you had PMM you can get a very educated guess about the size looking at the graph “Innodb Log File Usage Hourly”. The idea is that you have a redo log size big enough to hold at least one hour of transactions.
1 Like
Hi!
Thanks for your answers 
I’ve updated xtrabackup to version 8.0.32-26 and moved the backup to the replica.
And I’ve set-up the innodb_redo_log_capacity to 128Gb (it was previously at 64Gb).
Can I have some problems with such a high value? (other than disk usage)
The backup is running now, I will keep you updated.
Backup has been completed successfully, thanks for your help
Backups from replicas are good ONLY if you have ensured the data is an exact copy from source. Please use pt-table-checksum — Percona Toolkit Documentation to ensure the data is the same BEFORE you backup from a replica.
2 Likes