backup-lock-timeout and backup-lock-retry-count do not work
General
Escalation
General
Escalation
Description
Environment
None
Smart Checklist
Activity
Show:
Aaditya Dubey January 28, 2024 at 1:43 PM
Hi @Jinghua Lin
Thank you for the report.
Verified as described:
Tested on Following version fo PXB:
PXB-2.4.29
PXB-8.0.35
1. Started PS 5.7.43 & PS 8.0.35
2. Executed following SQL statements on both 5.7 & 8.0
mysql [localhost:5744] {msandbox} ((none)) > use test
Database changed
mysql [localhost:5744] {msandbox} (test) > create table t1(id int, name char(1));
Query OK, 0 rows affected (0.02 sec)
mysql [localhost:5744] {msandbox} (test) > LOCK TABLE test.t1 WRITE;
Query OK, 0 rows affected (0.00 sec)
3. Created backup directory
4. Executed following PXB command on 5.7
$:~/percona-xtrabackup-2.4.29-Linux-x86_64.glibc2.17-minimal/bin$ ./xtrabackup --defaults-file=$HOME/sandboxes/msb_ps5_7_43/my.sandbox.cnf --user=msandbox --password=msandbox --host=127.0.0.1 --backup --databases=test --target-dir=$HOME/xtra_backup --backup-lock-timeout=2 --backup-lock-retry-count=1
xtrabackup: recognized server arguments: --datadir=$HOME/sandboxes/msb_ps5_7_43/data --tmpdir=$HOME/sandboxes/msb_ps5_7_43/tmp
xtrabackup: recognized client arguments: --user=msandbox --password=* --port=5744 --socket=/tmp/mysql_sandbox5744.sock --user=msandbox --password=* --host=127.0.0.1 --backup=1 --databases=test --target-dir=$HOME/xtra_backup --backup-lock-timeout=2 --backup-lock-retry-count=1
240128 13:32:47 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=127.0.0.1;port=5744;mysql_socket=/tmp/mysql_sandbox5744.sock' as 'msandbox' (using password: YES).
240128 13:32:47 version_check Connected to MySQL server
240128 13:32:47 version_check Executing a version check against the server...
240128 13:32:47 version_check Done.
240128 13:32:47 Connecting to MySQL server host: 127.0.0.1, user: msandbox, password: set, port: 5744, socket: /tmp/mysql_sandbox5744.sock
Using server version 5.7.43-47
./xtrabackup version 2.4.29 based on MySQL server 5.7.44 Linux (x86_64) (revision id: 2e6c0951)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to $HOME/sandboxes/msb_ps5_7_43/data
xtrabackup: open files limit requested 0, set to 1024
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
InnoDB: Number of pools: 1
240128 13:32:47 >> log scanned up to (2815278)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 29 for test/t1, old maximum was 0
Skipping db: ./mysql
Skipping db: ./sys
Skipping db: ./performance_schema
240128 13:32:47 [01] Copying ./ibdata1 to $HOME/xtra_backup/ibdata1
240128 13:32:47 [01] ...done
240128 13:32:47 [01] Copying ./test/t1.ibd to $HOME/xtra_backup/test/t1.ibd
240128 13:32:47 [01] ...done
240128 13:32:48 >> log scanned up to (2815278)
240128 13:32:48 Executing LOCK TABLES FOR BACKUP...
240128 13:32:49 >> log scanned up to (2815278)
240128 13:32:50 >> log scanned up to (2815278)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transaction
240128 13:32:51 >> log scanned up to (2815278)
240128 13:32:51 Executing LOCK TABLES FOR BACKUP...
240128 13:32:52 >> log scanned up to (2815278)
240128 13:32:53 >> log scanned up to (2815278)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transaction
240128 13:32:54 >> log scanned up to (2815278)
i see --backup-lock-timeout=2 --backup-lock-retry-count=1 these are ineffect
But in 8.0 they are not working at all:
$:~/percona-xtrabackup-8.0.35-30-Linux-x86_64.glibc2.17-minimal/bin$ ./xtrabackup --defaults-file=$HOME/sandboxes/msb_ps8_0_35/my.sandbox.cnf --user=msandbox --password=msandbox --host=127.0.0.1 --backup --databases=test --target-dir=$HOME/xtra_backup --backup-lock-timeout=2 --backup-lock-retry-count=1
2024-01-28T13:22:40.944544-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=$HOME/sandboxes/msb_ps8_0_35/data --tmpdir=$HOME/sandboxes/msb_ps8_0_35/tmp
2024-01-28T13:22:40.944733-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --user=msandbox --password=* --port=8040 --socket=/tmp/mysql_sandbox8040.sock --user=msandbox --password=* --host=127.0.0.1 --backup=1 --databases=test --target-dir=$HOME/xtra_backup --backup-lock-timeout=10 --backup-lock-retry-count=10
./xtrabackup version 8.0.35-30 based on MySQL server 8.0.35 Linux (x86_64) (revision id: 6beb4b49)
240128 13:22:41 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=127.0.0.1;port=8040;mysql_socket=/tmp/mysql_sandbox8040.sock' as 'msandbox' (using password: YES).
240128 13:22:41 version_check Connected to MySQL server
240128 13:22:41 version_check Executing a version check against the server...
240128 13:22:41 version_check Done.
2024-01-28T13:22:41.045602-00:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: 127.0.0.1, user: msandbox, password: set, port: 8040, socket: /tmp/mysql_sandbox8040.sock
2024-01-28T13:22:41.055062-00:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.35-27
2024-01-28T13:22:41.057888-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP ...
^Csending the contact to Engineering for further review and updates.
Jinghua Lin April 24, 2022 at 6:30 AM
@aaditya.dubey
The output of "SHOW PROCESSLIST;" before starting the backup:
mysql> show processlist;
+---------+-------------+-------------------+------+------------------+---------+---------------------------------------------------------------+-------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+---------+-------------+-------------------+------+------------------+---------+---------------------------------------------------------------+-------------------------------+
| 1810064 | repl | 192.168.60.6:57340 | NULL | Binlog Dump GTID | 3531782 | Master has sent all binlog to slave; waiting for more updates | NULL |
| 5445220 | root | localhost | kk | Query | 178 | User sleep | select sleep(10000) from test |
| 5445225 | root | localhost | NULL | Query | 0 | starting | show processlist |
+---------+-------------+-------------------+------+------------------+---------+---------------------------------------------------------------+-------------------------------+
3 rows in set (0.00 sec)
I exeuted "select sleep(10000) from test" in order to simulate a long-running sql which appears in the usual and FTWRL would get stuck by select
The special thing is that 8.0 needs to create MyISAM table before starting the backup. Otherwise xtrabackup will not execute FTWRL.
--backup-lock-timeout and --backup-lock-retry-count should be effective in this situation. But now the result is:
5.7 --backup-lock-timeout is effective; --backup-lock-retry-count is ineffective.
8.0 both of two variables are ineffective.
Note that all the cases I mentioned above are FTWRL.
Aaditya Dubey April 19, 2022 at 8:00 AM
Hi @Jinghua Lin,
Thank you for the updates.
please let me know what operation is being running when backup is getting started, please share output of "SHOW PROCESSLIST;" which will be helpful to see what threads is being running while backup is in progress.
Jinghua Lin April 17, 2022 at 7:31 AM
@Aaditya Dubey
Sorry, I may not have expressed myself clearly. I didn't think the two parameters were completely useless. It may be normal under both LOCK TABLE FOR BACKUP and LOCK BINLOG FOR BACKUP statements, but my concern is FLUSH TABLES WITH READ LOCK. Your test is completely different from mine and does not solve my problem.
Aaditya Dubey April 15, 2022 at 1:29 PM
Hi @Jinghua Lin,
Thanks for the updates.
i have executed sleep query to simulate long running sql but it is not impacting the backup thread in any ways, however i tried putting write lock on the table which actually reproduce the issue, please check below.
mysql [localhost:5725] {msandbox} (test) > LOCK TABLE test.sbtest1 WRITE;
Query OK, 0 rows affected (0.01 sec)
...
220415 08:56:30 >> log scanned up to (496709669)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transaction
220415 08:56:31 >> log scanned up to (496709669)
220415 08:56:32 Executing LOCK TABLES FOR BACKUP...
220415 08:56:32 >> log scanned up to (496709669)
220415 08:56:33 >> log scanned up to (496709669)
220415 08:56:34 >> log scanned up to (496709669)
220415 08:56:35 >> log scanned up to (496709669)
220415 08:56:36 >> log scanned up to (496709669)
220415 08:56:37 >> log scanned up to (496709669)
220415 08:56:38 >> log scanned up to (496709669)
220415 08:56:39 >> log scanned up to (496709669)
220415 08:56:40 >> log scanned up to (496709669)
220415 08:56:41 >> log scanned up to (496709669)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transaction
220415 08:56:42 >> log scanned up to (496709669)
220415 08:56:43 Executing LOCK TABLES FOR BACKUP...
220415 08:56:43 >> log scanned up to (496709669)
220415 08:56:45 >> log scanned up to (496709669)
220415 08:56:46 >> log scanned up to (496709669)
220415 08:56:47 >> log scanned up to (496709669)
220415 08:56:48 >> log scanned up to (496709669)
220415 08:56:49 >> log scanned up to (496709669)
220415 08:56:50 >> log scanned up to (496709669)
220415 08:56:51 >> log scanned up to (496709669)
220415 08:56:52 >> log scanned up to (496709669)
220415 08:56:53 >> log scanned up to (496709669)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transaction
220415 08:56:54 >> log scanned up to (496709669)
220415 08:56:54 Executing LOCK TABLES FOR BACKUP...
220415 08:56:55 >> log scanned up to (496709669)
220415 08:56:56 >> log scanned up to (496709669)
220415 08:56:57 >> log scanned up to (496709669)
220415 08:56:58 >> log scanned up to (496709669)
220415 08:56:59 >> log scanned up to (496709669)
220415 08:57:00 >> log scanned up to (496709669)
220415 08:57:01 >> log scanned up to (496709669)
220415 08:57:02 >> log scanned up to (496709669)
220415 08:57:03 >> log scanned up to (496709669)
220415 08:57:04 >> log scanned up to (496709669)
Error: failed to execute query 'LOCK TABLES FOR BACKUP': 1205 (HY000) Lock wait timeout exceeded; try restarting transactionFirst of all i would like to say that it is not a bug because there are some locks which impacting the backup thread so please retry the backup also please run the "SHOW PROCESSLIST;" and see what is impacting the backup thread also i would like to recommend that if facing frequent locking issue then take backup at non-peak hours.
Details
Assignee
UnassignedUnassignedReporter
Jinghua LinJinghua LinAffects versions
Priority
Low
Details
Details
Assignee
Unassigned
UnassignedReporter
Jinghua LinAffects versions
Priority
LowSmart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Created March 28, 2022 at 3:00 PM
Updated March 6, 2024 at 6:28 PM
In MySQL 5.7.25(xtrabackup 2.4.24):
I used the following backup command:
xtrabackup --defaults-file=/opt/mysql/etc/3306/my.cnf --user=root --password=123456 --host=127.0.0.1 --backup --target-dir=backup --backup-lock-timeout=10 --backup-lock-retry-count=10
Then I noticed that the timeout was in effect, but it didn't retry after the timeout.
220328 22:36:08 >> log scanned up to (6169350902) 220328 22:36:08 Executing FLUSH NO_WRITE_TO_BINLOG TABLES... 220328 22:36:09 >> log scanned up to (6169350902) 220328 22:36:10 >> log scanned up to (6169350902) 220328 22:36:11 >> log scanned up to (6169350902) 220328 22:36:12 >> log scanned up to (6169350902) 220328 22:36:13 >> log scanned up to (6169350902) 220328 22:36:14 >> log scanned up to (6169350902) 220328 22:36:15 >> log scanned up to (6169350902) 220328 22:36:16 >> log scanned up to (6169350902) 220328 22:36:17 >> log scanned up to (6169350902) 220328 22:36:18 >> log scanned up to (6169350902) Error: failed to execute query 'FLUSH NO_WRITE_TO_BINLOG TABLES': 1205 (HY000) Lock wait timeout exceeded; try restarting transactionSame experiment in MySQL 8.0.25(xtrabackup 8.0.27-19):
Both parameters don't work anymore
220328 22:50:05 >> log scanned up to (8515046226) 220328 22:50:05 Executing FLUSH NO_WRITE_TO_BINLOG TABLES... 220328 22:50:06 >> log scanned up to (8515046226) 220328 22:50:07 >> log scanned up to (8515046226) 220328 22:50:08 >> log scanned up to (8515046226) 220328 22:50:09 >> log scanned up to (8515046226) 220328 22:50:10 >> log scanned up to (8515046226) 220328 22:50:11 >> log scanned up to (8515046226) 220328 22:50:12 >> log scanned up to (8515046226) 220328 22:50:13 >> log scanned up to (8515046226) 220328 22:50:14 >> log scanned up to (8515046226) 220328 22:50:15 >> log scanned up to (8515046226) 220328 22:50:16 >> log scanned up to (8515046226) 220328 22:50:17 >> log scanned up to (8515046226) 220328 22:50:18 >> log scanned up to (8515046226) 220328 22:50:19 >> log scanned up to (8515046226) 220328 22:50:20 >> log scanned up to (8515046226) 220328 22:50:21 >> log scanned up to (8515046226) 220328 22:50:22 >> log scanned up to (8515046226) 220328 22:50:23 >> log scanned up to (8515046226) 220328 22:50:24 >> log scanned up to (8515046226) 220328 22:50:25 >> log scanned up to (8515046226) 220328 22:50:26 >> log scanned up to (8515046226) 220328 22:50:27 >> log scanned up to (8515046226) 220328 22:50:28 >> log scanned up to (8515046226) ^CAccording to the information, these two parameters should take effect for FTWRL (or flush tables).
I'm not sure if there's something wrong with the way I'm using it or if this is a bug.