I occured the following case irregularly When I backup my instance from slave.
Some slaves are behind and hung with status “Waiting for binlog lock” while xtrabackup is running.
Server version: 5.7.21-20-log Percona Server (GPL), Release 20, Revision ed217b06ca3
Xtrabackup version: 2.14.11 percona-xtrabackup-2.4.11-Linux-x86_64.libgcrypt20.tar.gz
GTID and Multi Thread Slave is enable.
Seconds_Behind_Master: 1261
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: 16213303
Master_UUID: f989cf96-250d-11e8-be75-509a4c7eeb80
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Waiting for dependent transaction to commit
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: f989cf96-250d-11e8-be75-509a4c7eeb80:67655-7326590789
Executed_Gtid_Set: 0baaafc8-2c1e-11e8-9a4c-509a4c799aa8:1-3,
f989cf96-250d-11e8-be75-509a4c7eeb80:1-7321262637
Auto_Position: 1
the processlist is :
root@localhost [(none)] 15:30:37> show full processlist;
±-------±------------±----------------±-----±--------±-------±--------------------------------------------±-----------------------±----------±--------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
±-------±------------±----------------±-----±--------±-------±--------------------------------------------±-----------------------±----------±--------------+
| 2026 | system user | | NULL | Connect | 432609 | Waiting for master to send event | NULL | 0 | 0 |
| 2027 | system user | | NULL | Connect | 1329 | Waiting for dependent transaction to commit | NULL | 0 | 0 |
| 2028 | system user | | NULL | Connect | 1330 | Waiting for preceding transaction to commit | NULL | 0 | 0 |
| 2029 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2030 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2031 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2032 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2033 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2034 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2035 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2036 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2037 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2038 | system user | | NULL | Connect | 1330 | Waiting for binlog lock | NULL | 0 | 0 |
| 2039 | system user | | NULL | Connect | 1330 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 2040 | system user | | NULL | Connect | 1330 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 2041 | system user | | NULL | Connect | 1330 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 2042 | system user | | NULL | Connect | 1330 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 2043 | system user | | NULL | Connect | 1330 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 404742 | bkpuser | localhost | NULL | Query | 1329 | Waiting for binlog lock | LOCK BINLOG FOR BACKUP | 0 | 0 |
| 406434 | root | localhost | NULL | Query | 0 | starting | show full processlist | 0 | 0 |
the backup command is " innobackupex --defaults-file=/hbdata/promysql/bin/my.cnf --user=bkpuser --password=x xxxxxxxxxxxxxx --host=localhost --port=3303 --socket=/hbdata/promysql/mydata/mysqld.sock --no-version-check --parallel=4 --throttle=2000 --use-memory=16GB --slave-info --rsync --tmpdir=/hbdata/innobackuptmp --incremental --incremental-basedir=/backup/pro/xtrabackup/20180605/ful/2018-06-05_07-00-01 /backup/pro/xtrabackup/20180605/inc/"
When I kiiled the backup connections, slave thread is normal.
The stace info is : strace -p
stat(“ib_buffer_pool”, {st_mode=S_IFREG|0640, st_size=106599220, …}) = 0
stat(“ib_lru_dump”, 0x7ffdb861d270) = -1 ENOENT (No such file or directory)
write(6, “vent_name.frm\n./performance_sche”…, 3543) = 3543
close(6) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=414, …}) = 0
write(2, “180529 10:10:17 Starting rsync a”…, 149) = 149
rt_sigaction(SIGINT, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], , 8) = 0
clone(child_stack=0, flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0x7ffdb861ce9c) = 66770
wait4(66770, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 66770
rt_sigaction(SIGINT, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN, , SA_RESTORER, 0x7fe83c5dc4b0}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, , NULL, 8) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=414, …}) = 0
write(2, “180529 10:10:17 rsync finished s”…, 45) = 45
open("/tmp/xtrabackup_rsyncfiles_pass1", O_RDONLY) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=11735, …}) = 0
read(6, “./mysql/user.MYI\n./mysql/ndb_bin”…, 4096) = 4096
read(6, “G\n./sys/innodb_buffer_stats_by_t”…, 4096) = 4096
read(6, “vent_name.frm\n./performance_sche”…, 4096) = 3543
read(6, “”, 4096) = 0
close(6) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=414, …}) = 0
write(2, “180529 10:10:17 Finished backing”…, 64) = 64
close(7) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=414, …}) = 0
write(2, “180529 10:10:17 Executing LOCK B”…, 52) = 52
sendto(3, “\27\0\0\0\3LOCK BINLOG FOR BACKUP”, 27, 0, NULL, 0) = 27
recvfrom(3,
Then it will always wait 。
