When does xtrabackup take lock exactly and why there's slave lag after backup starts?
0
votes
0
answers
35
views
MySQL Version -- MySQL Community Server 5.7.44
Percona xtrabackup Version 2.4.29 (x86_64)
I want to understand when does xtrabackup exactly take the FLUSH TABLES WITH READ LOCK.
Following is the simplified command I use for full backup.
/usr/bin/xtrabackup --defaults-file=/etc/my.cnf --backup --slave-info --login-path=bkp_user --tmpdir=/pfg_prod/tmp --parallel=4 --use-memory=1024M 2> bkp.log --stream=xbstream | /usr/bin/lz4 stdin /bkp_dir/date.lz4
I use this same command on all my slave servers for daily backups.
When I check the xtrabackup logs, I notice that it does not immediately take FTWRL but the slave lag begins to grow.
Log for the 9th
250309 11:13:18 Executing FLUSH TABLES WITH READ LOCK...
250309 11:13:32 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
250309 11:13:32 Executing UNLOCK TABLES
Log for the 10th
250310 11:13:55 Executing FLUSH TABLES WITH READ LOCK...
250310 11:14:05 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
250310 11:14:05 Executing UNLOCK TABLES
Log for the 15th
250315 11:21:17 Executing FLUSH TABLES WITH READ LOCK...
250315 11:21:18 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
250315 11:21:18 Executing UNLOCK TABLES
***The backup starts at 08:00 AM every morning.***
Thus, if it starts the backup at 08:00 AM and executes the FTWRL at around after 11:00 AM, I want to understand why there's slave lag immediately after the backup starts and the lag continues till the backup is over.
***I want to understand when does xtrabackup exactly take the FLUSH TABLES WITH READ LOCK if not at the start of the backup? and why there's slave lag as soon as the backup starts, because if the FTWRL is taken after approximately 3 hours, I think there shouldn't be lag before that, I am not sure though. The slave lag is only during the backup window.***
I had been assuming so far that FTWRL is taken when the backup starts, hence the doubt.
root@localhost 09:45:21 [(none)] show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: master_ip
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: binlog.000982
Read_Master_Log_Pos: 30958
Relay_Log_File: relay.000430
Relay_Log_Pos: 1058083259
Relay_Master_Log_File: binlog.000981
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 10580
Relay_Log_Space: 1383
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 5872
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 103454371
Master_UUID: UUID
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: System lock
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: GTID-SET
Executed_Gtid_Set: GTID-SETS
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.25 sec)
+-------+-------------------+---------------------+-------------------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-------+-------------------+---------------------+-------------------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+ |
| 13 | system user | | NULL | Connect | 255661 | Waiting for master to send event | NULL |
| 14 | system user | | NULL | Connect | 0 | Waiting for dependent transaction to commit | NULL |
| 15 | system user | | NULL | Connect | 5931 | System lock | NULL |
| 16 | system user | | NULL | Connect | 5931 | Waiting for an event from Coordinator | NULL |
| 12664 | bkp_user | localhost | NULL | Sleep | 6377 | | NULL | |
| 12989 | root | localhost | NULL | Query | 0 | starting | show processlist |
| 12990 | prome | 127.0.0.1:43240 | NULL | Query | 0 | Opening tables | SELECT table_schema, table_name, column_name, auto_increment,
pow(2, case data_type
when ' |
+-------+-------------------+---------------------+-------------------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
Asked by Avinash Pawar
(216 rep)
Mar 16, 2025, 09:37 AM
Last activity: Mar 17, 2025, 02:24 AM
Last activity: Mar 17, 2025, 02:24 AM