最近在我们线上库物理备份的时候出现一个奇怪的现象：
我们备份都在从库上备份的，在业务低一般是在晚上2点钟开始备份.有天发现从库的延迟一直在增加，登录上实例，通过show processlist 发现，sql 线程在等待 binlog lock。同时看到我们从2点钟开始的压缩远程备份并没有完成，备份日志还在扫面ibd文件。
那么这个binlog lock 是谁持有的呢？仔细想想我们的业务场景，这是一个只读从库，且库上便没有提供任何读的服务，唯一的一个疑点就是我们的备份导致的，通过show processlist 可以看到，Time列的数值 均是18510，两个时间上边吻合，那么问题可以初步确认是由于备份引起的。
mysql> show processlist;
+---------+-------------+-----------+------------+---------+-------+-----------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+---------+-------------+-----------+------------+---------+-------+-----------------+
| 4613465 | system user | | NULL | Connect | 65348 | Waiting for master to send event | NULL | 0 | 0 |
| 4613466 | system user | | NULL | Connect | 18510 | Waiting for binlog lock | NULL | 0 | 0 |
| 4631056 | dbbackup | localhost | NULL | Sleep | 18510 | | NULL | 0 | 0 |
进一步的，我们去找找官文，看看什么时候xtrabackup 会用到这个binlog lock 呢？截取一段出来：
LOCK TABLES FOR BACKUP
... copy .frm, MyISAM, CSV, etc. ...
LOCK BINLOG FOR BACKUP
UNLOCK TABLES
... get binlog coordinates ...
... wait for redo log copying to finish ...
UNLOCK BINLOG
可以看到，Binlog Lock是在备份的尾声阶段，是为了在获取Master 或者slave 的一致性位置点而是用的。
那么问题来了， 我们的备份现在是到了那个阶段呢？如果已经到了尾声阶段，那么这个锁Binlog的过程应该是很短暂的。
为了确认我们当前备份的一个状态， 使用strace -p{pid} 来看一下，当前xtrabackup、innobackupex 都在做些什么事情。
在通过strace 查看这个进程到底在做什么事之前， 我们先来看看一些前埔的知识：
由于我们备份MySQL 是主要用到 innobackupex 和 xtrabackup，前者是一个 perl 脚本，后者是 C/C++ 编译的二进制。
xtrabackup 是用来备份 InnoDB 表的，不能备份非 InnoDB 表，和 mysqld server 没有交互；而innobackupex 脚本用来备份非 InnoDB 表，同时会调用 xtrabackup 命令来备份 InnoDB 表，还会和 mysqld server 发送命令进行交互，如加读锁（FTWRL）、获取位点（SHOW SLAVE STATUS）等。简单来说，innobackupex 在 xtrabackup 之上做了一层封装。
一般情况下，我们是希望能备份 MyISAM 表的，虽然我们可能自己不用 MyISAM 表，但是 mysql 库下的系统表是 MyISAM 的，因此备份基本都通过 innobackupex 命令进行；另外一个原因是我们可能需要保存位点信息。
那么一个perl脚步和C程序是如何进行通信的呢？它们是如何知道撒时候该执行什么步骤的呢？
2个工具之间的交互和协调是通过控制文件的创建和删除来实现的，主要文件有：
xtrabackup_suspended_1
xtrabackup_suspended_2
xtrabackup_log_copied
来看一张图，了解一下innobackupex 和 xtrabackup 之间是如何协调的
举个栗子，我们来看备份时 xtrabackup_suspended_2 是怎么来协调2个工具进程的
innobackupex 在启动 xtrabackup 进程后，会一直等 xtrabackup 备份完 InnoDB 文件，方式就是等待 xtrabackup_suspended_2 这个文件被创建出来；
xtrabackup 在备完 InnoDB 数据后，就在指定目录下创建出这个文件，然后等这个文件被 innobackupex 删除；
innobackupex 检测到文件 xtrabackup_suspended_2 被创建出来后，就继续往下走；
innobackupex 在备份完非 InnoDB 表后，删除 xtrabackup_suspended_2 这个文件，这样就通知 xtrabackup 可以继续了，然后等 xtrabackup_log_copied 被创建；
xtrabackup 检测到 xtrabackup_suspended_2 文件删除后，就可以继续往下了。
是不是感觉有点不可思议，通过文件是否存在来控制进程，这种方式非常的不靠谱，因为非常容易被外部干扰，比如文件被别人误删掉，或者2个正在跑的备份控制文件误放在同一个目录下，就等着备份乱掉吧，但是 Percona 就是这么干的。
---------------------------------------OK ,开启我们的debug 模式-----------------------------------------------------------------
有了一个大概的概念后，我们继续，用strace来瞅瞅我们这两个备份的进程都在干撒？为什么会长期持有binlog 锁不释放呢？
首先我们看一下 xtrabackup这个进程是在做什么：
/usr/bin/xtrabackup --defaults-file=/data/mysql/xxxx/my.cnf --defaults-group=mysqld --backup --suspend-at-end --target-dir=/tmp --innodb_data_file_path=ibdata1:12M:autoextend --tmpdir=/tmp --extra-lsndir=/
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=5, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}
可以看到，我们的xtrabackup 当前是在判断 xtrabackup_suspended_2 这个文件的状态，因为我们拷贝完了ibd 文件。创建了 xtrabackup_suspended_2 这个文件，通知我们的innobackupex ，我的ibd 文件拷贝完成了，等待下一步的指令,也就是说等待这个文件被删除。
那么继续我们再看看innobackupex ，看看他又在做什么事情：
perl /usr/bin/innobackupex --ibbackup=/usr/bin/xtrabackup --defaults-file=/data/mysql/xxxxx/my.cnf --user=dbbackup --password=xxxxxx --slave-info --stream=tar /tmp
stat("/tmp/xtrabackup_log_copied", 0x7c6130) = -1 ENOENT (No such file or directory)
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, 0x7fff9aad0750) = 0
wait4(21337, 0x7fff9aad077c, WNOHANG, NULL) = 0
可以看到它在等待 xtrabackup_log_copied 文件被创建。
到此，我们可以看到，innobackupex 和xtrabackup 现在处于在两个不同的层级上了，innobackupex 已经超前了xtrabackup，认为当前的xtrackup 下一步应该创建文件告诉我redlog已经拷贝完成了。
那么到此，我们已经很明显的看到 这个备份已经乱掉了。
ok，既然问题已经弄明白了， 那么我们有什么应对策略呢？
1. 备份时间尽量错开，两个实例之间备份预留足够大的备份时间
2. 备份的临时目录指定到不同的地方，避免实例间备份互相干扰
3. 在2.3 版本以上 innobackupex 已经用C语言重写了innobackupex，升级到次版本即可解决
===================================================================================
附一个的xtrackup 备份过程堆栈日志(只保留通信间协调信息)：
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
write(2, "xtrabackup: Creating suspend fil"..., 80) = 80
open("/tmp/xtrabackup_suspended_2", O_WRONLY|O_CREAT|O_EXCL|O_NOFOLLOW, 0660) = 7
write(7, "1588", 4) = 4
close(7) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=4, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=4, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=4, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=4, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=4, ...}) = 0
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
stat("/tmp/xtrabackup_suspended_2", 0x7fffe0e0a970) = -1 ENOENT (No such file or directory)
pread(4, "\0\0\0\0\0\23\32\36\0\0\0\2\203o\215\223CY=\223\4\0\0\0\377\377\377\377\377\377\377\377"..., 4096, 4096) = 4096
pread(4, "\0\0\0\0\0\23\32\37\0\0\0\2\203o\217,CY?,\4\0\0\0\377\377\377\377\377\377\377\377"..., 4096, 12288) = 4096
pread(4, "\0\0\0\0\0\23\32\37\0\0\0\2\203o\217,CY?,\4\0\0\0\377\377\377\377\377\377\377\377"..., 4096, 12288) = 4096
write(2, "xtrabackup: The latest check poi"..., 68) = 68
futex(0x1bef89c, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x1bef860, 46) = 1
futex(0x1bef860, FUTEX_WAKE_PRIVATE, 1) = 1
write(2, "xtrabackup: Stopping log copying"..., 41) = 41
write(2, ".", 1) = 1
select(0, NULL, NULL, NULL, {0, 200000}) = 0 (Timeout)
write(2, "\n", 1) = 1
write(2, "xtrabackup: Creating suspend fil"..., 79) = 79
open("/tmp/xtrabackup_log_copied", O_WRONLY|O_CREAT|O_EXCL|O_NOFOLLOW, 0660) = 7
write(7, "1588", 4) = 4
close(7) = 0
open("/tmp/xbtempjD8Ghu", O_RDWR|O_CREAT|O_EXCL, 0600) = 7
unlink("/tmp/xbtempjD8Ghu") = 0
write(7, "backup_type = full-backuped\nfrom"..., 97) = 97
fadvise64(7, 0, 0, POSIX_FADV_DONTNEED) = 0
open("/tmp/xtrabackup_checkpoints", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(8, "backup_type = full-backuped\nfrom"..., 97) = 97
close(8) = 0
write(1, "xtrabackup_logfile\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
===================================================================================
附innobackupex 备份间通信日志：
wait4(18608, 0x7fffa4d91c1c, WNOHANG, NULL) = 0
stat("/tmp/xtrabackup_suspended_2", 0x249f130) = -1 ENOENT (No such file or directory)
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, 0x7fffa4d91bf0) = 0
wait4(18608, 0x7fffa4d91c1c, WNOHANG, NULL) = 0
......................
stat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=5, ...}) = 0
write(2, "161101 10:25:56 innobackupex: E"..., 67) = 67
sendto(3, "\27\0\0\0\3LOCK BINLOG FOR BACKUP", 27, 0, NULL, 0) = 27
sendto(3, "\22\0\0\0\3SHOW SLAVE STATUS", 22, 0, NULL, 0) = 22
sendto(3, "\17\0\0\0\3SHOW VARIABLES", 19, 0, NULL, 0) = 19
open("/tmp/xtrabackup_slave_info", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4 = 0
lstat("/tmp/xtrabackup_slave_info", {st_mode=S_IFREG|0644, st_size=77, ...}) = 0
unlink("/tmp/xtrabackup_slave_info") = 0
sendto(3, "\23\0\0\0\3SHOW MASTER STATUS", 23, 0, NULL, 0) = 23
open("/tmp/xtrabackup_binlog_info", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
lstat("/tmp/xtrabackup_binlog_info", {st_mode=S_IFREG|0644, st_size=27, ...}) = 0
unlink("/tmp/xtrabackup_binlog_info") = 0
sendto(3, "%\0\0\0\3FLUSH NO_WRITE_TO_BINLOG EN"..., 41, 0, NULL, 0) = 41
lstat("/tmp/xtrabackup_suspended_2", {st_mode=S_IFREG|0640, st_size=5, ...}) = 0
unlink("/tmp/xtrabackup_suspended_2") = 0
stat("/tmp/xtrabackup_log_copied", 0x1ce5130) = -1 ENOENT (No such file or directory)
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, {0, 583650111}) = ? ERESTART_RESTARTBLOCK (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
restart_syscall(<... resuming interrupted call ...>) = 0
wait4(17273, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 17273
stat("/tmp/xtrabackup_log_copied", {st_mode=S_IFREG|0640, st_size=5, ...}) = 0
lstat("/tmp/xtrabackup_log_copied", {st_mode=S_IFREG|0640, st_size=5, ...}) = 0
unlink("/tmp/xtrabackup_log_copied") = 0
sendto(3, "\16\0\0\0\3UNLOCK BINLOG", 18, 0, NULL, 0) = 18
sendto(3, "\16\0\0\0\3UNLOCK TABLES", 18, 0, NULL, 0) = 18
recvfrom(3, "\7\0\0\1\0\0\0\2\0\0\0", 16384, 0, NULL, NULL) = 11
write(2, "161101 10:25:57 innobackupex: A"..., 51) = 51
lstat("/tmp/xtrabackup_pid", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
unlink("/tmp/xtrabackup_pid") = 0
stat("/data/mysql/3307//ib_buffer_pool", {st_mode=S_IFREG|0660, st_size=1244, ...}) = 0
write(2, "\ninnobackupex: Backup created in"..., 50) = 50
write(2, "innobackupex: MySQL binlog posit"..., 85) = 85
write(2, "innobackupex: MySQL slave binlog"..., 119) = 119
sendto(3, "\26\0\0\0\3SELECT UUID() AS uuid", 26, 0, NULL, 0) = 26
参考doc：
1. 现象描述 https://bugs.launchpad.net/percona-server/+bug/1527463
2. 备份锁策略 https://www.percona.com/doc/percona-server/5.6/management/backup_locks.html
3. 淘宝内核月报 http://mysql.taobao.org/monthly/2016/03/07/
