We’re running XtraBackup 8.0.25 with this command :
xtrabackup --parallel=2 --rsync --user=root --password=xxxxx --backup --throttle=10 --target-dir=/var/backup/mysql
While this is running, the database appears to be completely locked. We also see in the output :
210714 13:31:10 Connecting to MySQL server host: localhost, user: root, password: set, port: 3306, socket: /var/lib/mysql/mysql.sock
Using server version 8.0.25 210714 13:31:10 Executing LOCK INSTANCE FOR BACKUP…
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
xtrabackup: open files limit requested 0, set to 8000
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
Number of pools: 1
xtrabackup: inititialize_service_handles suceeded
210714 13:31:10 Connecting to MySQL server host: localhost, user: root, password: set, port: 3306, socket: /var/lib/mysql/mysql.sock
xtrabackup: Redo Log Archiving is not set up.
Starting to parse redo log at lsn = 893199925275
Recovery parsing buffer extended to 4194304.
210714 13:31:10 >> log scanned up to (893203184714)
xtrabackup: Generating a list of tablespaces
xtrabackup: Generating a list of tablespaces
Scanning ‘./’
Completed space ID check of 2 files.
Allocated tablespace ID 1922 for mloms/acl_classes, old maximum was 0
210714 13:31:11 >> log scanned up to (893203187354)
210714 13:31:12 >> log scanned up to (893203189994)
210714 13:31:13 >> log scanned up to (893203194594)
210714 13:31:14 >> log scanned up to (893203197917)
210714 13:31:15 >> log scanned up to (893203200573)
210714 13:31:16 >> log scanned up to (893203203213)
210714 13:31:17 >> log scanned up to (893203215201)
210714 13:31:18 >> log scanned up to (893203218761)
210714 13:31:19 >> log scanned up to (893203220548)
Using undo tablespace ‘./undo_001’.
Using undo tablespace ‘./undo_002’.
Opened 2 existing undo tablespaces.
xtrabackup: Starting 2 threads for parallel data files transfer
210714 13:31:19 [02] Copying ./racktables/CachedPAV.ibd to /var/backup/mysql/racktables/CachedPAV.ibd
210714 13:31:19 [01] Copying ./racktables/VSIPs.ibd to /var/backup/mysql/racktables/VSIPs.ibd
210714 13:31:19 [02] …done
210714 13:31:19 [01] …done
Is this something that changed, because we didn’t experience this problem before ?
I see you are running with --rsync . Do you have many non-innodb tables?
Can you please show use the full output of your backup and also the output of SHOW PROCESSLIST from your mysql instance while the queries are blocked ?
We don’t have any non-innodb tables anymore at this point, so we could get rid of rsync.
This is part of the log (anonymized) :
xtrabackup: recognized server arguments: --datadir=/var/lib/mysql --datadir=/var/lib/mysql --log_bin=0 --innodb_buffer_pool_size=4G
xtrabackup: recognized client arguments: --port=3306 --socket=/var/lib/mysql/mysql.sock --host=localhost --user=root --password=* --parallel=2 --rsync=1 --user=root --password=* --backup=1 --throttle=10 --target-dir=/var/backup/mysql
xtrabackup version 8.0.25-17 based on MySQL server 8.0.25 Linux (x86_64) (revision id: d27028b)
210715 13:39:20 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=localhost;port=3306;mysql_socket=/var/lib/mysql/mysql.sock' as 'root' (using password: YES).
210715 13:39:20 version_check Connected to MySQL server
210715 13:39:20 version_check Executing a version check against the server...
210715 13:39:20 version_check Done.
210715 13:39:20 Connecting to MySQL server host: localhost, user: root, password: set, port: 3306, socket: /var/lib/mysql/mysql.sock
Using server version 8.0.25
210715 13:39:20 Executing LOCK INSTANCE FOR BACKUP...
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
xtrabackup: open files limit requested 0, set to 8000
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
Number of pools: 1
xtrabackup: inititialize_service_handles suceeded
210715 13:39:20 Connecting to MySQL server host: localhost, user: root, password: set, port: 3306, socket: /var/lib/mysql/mysql.sock
xtrabackup: Redo Log Archiving is not set up.
WARNING: unknown option --binlog-info=ON
Starting to parse redo log at lsn = 893895562790
Recovery parsing buffer extended to 4194304.
210715 13:39:20 >> log scanned up to (893898502881)
xtrabackup: Generating a list of tablespaces
xtrabackup: Generating a list of tablespaces
Scanning './'
Completed space ID check of 2 files.
Allocated tablespace ID 1922 for database2/acl_classes, old maximum was 0
210715 13:39:21 >> log scanned up to (893898509888)
210715 13:39:22 >> log scanned up to (893898513201)
210715 13:39:23 >> log scanned up to (893898516533)
210715 13:39:24 >> log scanned up to (893898521439)
210715 13:39:25 >> log scanned up to (893898524069)
210715 13:39:26 >> log scanned up to (893898526699)
210715 13:39:27 >> log scanned up to (893898529355)
210715 13:39:28 >> log scanned up to (893898532275)
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
xtrabackup: Starting 2 threads for parallel data files transfer
210715 13:39:29 [01] Copying ./database1/VSIPs.ibd to /var/backup/mysql/database1/VSIPs.ibd
210715 13:39:29 [02] Copying ./database1/CachedPAV.ibd to /var/backup/mysql/database1/CachedPAV.ibd
210715 13:39:29 [02] ...done
210715 13:39:29 [01] ...done
210715 13:39:29 [02] Copying ./database2/ara_email_user.ibd to /var/backup/mysql/database2/ara_email_user.ibd
210715 13:39:29 [01] Copying ./database2/db2_reservation_payment_details.ibd to /var/backup/mysql/database2/db2_reservation_payment_details.ibd
210715 13:39:29 [02] ...done
210715 13:39:29 [01] ...done
210715 13:39:29 [02] Copying ./database2/db2_log_event_archive.ibd to /var/backup/mysql/database2/db2_log_event_archive.ibd
210715 13:39:29 [01] Copying ./ibdata1 to /var/backup/mysql/ibdata1
210715 13:39:29 >> log scanned up to (893898534924)
210715 13:39:30 >> log scanned up to (893898537554)
210715 13:39:31 >> log scanned up to (893898540187)
210715 13:39:32 >> log scanned up to (893898543508)
210715 13:39:33 >> log scanned up to (893898543824)
210715 13:39:34 >> log scanned up to (893898551081)
210715 13:39:35 >> log scanned up to (893898553711)
210715 13:39:35 [01] ...done
210715 13:39:35 [01] Copying ./database2/ara_organization.ibd to /var/backup/mysql/database2/ara_organization.ibd
210715 13:39:35 [01] ...done
210715 13:39:35 [01] Copying ./database2/ara_rel_c3990ba69e0854fe1d2e0c.ibd to /var/backup/mysql/database2/ara_rel_c3990ba69e0854fe1d2e0c.ibd
210715 13:39:35 [01] ...done
210715 13:39:35 [01] Copying ./database2/ara_user_business_unit.ibd to /var/backup/mysql/database2/ara_user_business_unit.ibd
210715 13:39:36 [01] ...done
210715 13:39:36 [01] Copying ./database2/araopa_dm_campaign_summary.ibd to /var/backup/mysql/database2/araopa_dm_campaign_summary.ibd
210715 13:39:36 [01] ...done
210715 13:39:36 [01] Copying ./database2/araopa_zd_ticket_priority.ibd to /var/backup/mysql/database2/araopa_zd_ticket_priority.ibd
210715 13:39:36 [01] ...done
210715 13:39:36 [01] Copying ./database2/ara_rel_call_account_account_638472a8.ibd to /var/backup/mysql/database2/ara_rel_call_account_account_638472a8.ibd
210715 13:39:36 [01] ...done
210715 13:39:36 [01] Copying ./database1/VSPorts.ibd to /var/backup/mysql/database1/VSPorts.ibd
210715 13:39:36 [01] ...done
<part of log cut>
210715 13:41:10 [02] Copying ./database1/AttributeValue.ibd to /var/backup/mysql/database1/AttributeValue.ibd
210715 13:41:10 [02] ...done
210715 13:41:10 [02] Copying ./database2/db2_log_event.ibd to /var/backup/mysql/database2/db2_log_event.ibd
210715 13:41:11 >> log scanned up to (893898866750)
210715 13:41:11 [01] ...done
210715 13:41:11 [01] Copying ./database2/ara_email_thread.ibd to /var/backup/mysql/database2/ara_email_thread.ibd
210715 13:41:11 [01] ...done
210715 13:41:11 [01] Copying ./database2/ara_notification_recip_user.ibd to /var/backup/mysql/database2/ara_notification_recip_user.ibd
210715 13:41:11 [01] ...done
210715 13:41:11 [01] Copying ./undo_002 to /var/backup/mysql/undo_002
210715 13:41:12 >> log scanned up to (893898874409)
210715 13:41:13 >> log scanned up to (893898877725)
210715 13:41:13 [01] ...done
210715 13:41:13 [01] Copying ./undo_001 to /var/backup/mysql/undo_001
210715 13:41:14 >> log scanned up to (893898881054)
210715 13:41:15 >> log scanned up to (893898883694)
210715 13:41:15 [01] ...done
210715 13:41:16 >> log scanned up to (893898886324)
210715 13:41:17 >> log scanned up to (893898888969)
210715 13:41:18 >> log scanned up to (893898893057)
210715 13:41:19 >> log scanned up to (893898895690)
210715 13:41:20 >> log scanned up to (893898898320)
210715 13:41:21 >> log scanned up to (893898900950)
210715 13:41:22 >> log scanned up to (893898903596)
210715 13:41:23 >> log scanned up to (893898906226)
210715 13:41:24 >> log scanned up to (893898914126)
210715 13:41:25 >> log scanned up to (893898916756)
210715 13:41:26 >> log scanned up to (893898919386)
210715 13:41:27 >> log scanned up to (893898922730)
210715 13:41:28 >> log scanned up to (893898925656)
210715 13:41:29 >> log scanned up to (893898929000)
210715 13:41:30 >> log scanned up to (893898932373)
210715 13:41:31 >> log scanned up to (893898935003)
210715 13:41:32 >> log scanned up to (893898937633)
210715 13:41:33 >> log scanned up to (893898940972)
210715 13:41:34 >> log scanned up to (893898943612)
210715 13:41:35 >> log scanned up to (893898951297)
210715 13:41:36 >> log scanned up to (893898953927)
210715 13:41:37 >> log scanned up to (893898957243)
210715 13:41:37 [02] ...done
210715 13:41:38 Starting prep copy of non-InnoDB tables and files
210715 13:41:38 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass1 /var/backup/mysql/
210715 13:41:38 rsync finished successfully.
210715 13:41:38 Finished a prep copy of non-InnoDB tables and files
210715 13:41:38 Starting to backup non-InnoDB tables and files
210715 13:41:38 Starting rsync as: rsync -t . --files-from=/tmp/xtrabackup_rsyncfiles_pass2 /var/backup/mysql/
210715 13:41:38 rsync finished successfully.
210715 13:41:38 Finished backing up non-InnoDB tables and files
210715 13:41:38 Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
210715 13:41:38 Selecting LSN and binary log position from p_s.log_status
210715 13:41:38 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '893896461931'
xtrabackup: Stopping log copying thread at LSN 893898960562.
210715 13:41:38 >> log scanned up to (893898960572)
210715 13:41:39 Executing UNLOCK INSTANCE
210715 13:41:39 All tables unlocked
210715 13:41:39 Backup created in directory '/var/backup/mysql/'
210715 13:41:39 [00] Writing /var/backup/mysql/backup-my.cnf
210715 13:41:39 [00] ...done
210715 13:41:39 [00] Writing /var/backup/mysql/xtrabackup_info
210715 13:41:39 [00] ...done
xtrabackup: Transaction log of lsn (893895562989) to (893898963202) was copied.
210715 13:41:40 completed OK!
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata1:12M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=50331648 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=0 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/var/backup/mysql
xtrabackup version 8.0.25-17 based on MySQL server 8.0.25 Linux (x86_64) (revision id: d27028b)
xtrabackup: cd to /var/backup/mysql/
xtrabackup: This target seems to be not prepared yet.
Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=8388608, start_lsn=(893895562989)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 8388608
xtrabackup: inititialize_service_handles suceeded
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 8388608
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
PUNCH HOLE support available
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 595 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
The log sequence number 892000346036 in the system tablespace does not match the log sequence number 893895562989 in the ib_logfiles!
Database was not shutdown normally!
Starting crash recovery.
Starting to parse redo log at lsn = 893895562790, whereas checkpoint_lsn = 893895562989 and start_lsn = 893895562752
Doing recovery: scanned up to log sequence number 893898960562
Log background threads are being started...
Applying a batch of 1007 redo log records ...
10%
20%
30%
40%
50%
60%
70%
80%
90%
100%
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 2057635746
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.25 started; log sequence number 893898960562
Allocated tablespace ID 1919 for database1/VSEnabledPorts, old maximum was 0
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 893898960562
Number of pools: 1
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
PUNCH HOLE support available
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 595 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
Creating log file ./ib_logfile101
Creating log file ./ib_logfile1
Renaming log file ./ib_logfile101 to ./ib_logfile0
New log files created, LSN=893898960908
Starting to parse redo log at lsn = 893898960908, whereas checkpoint_lsn = 893898960908 and start_lsn = 893898960896
Log background threads are being started...
Applying a batch of 0 redo log records ...
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 2057635746
Removed temporary tablespace data file: "ibtmp1"
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.25 started; log sequence number 893898960908
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Trying to access missing tablespace 4294967294
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 893898960908
210715 13:41:48 completed OK!