解决Slave SQL线程Waiting for binlog lock

   最近在我们线上库物理备份的时候出现一个奇怪的现象：

   我们备份都在从库上备份的，在业务低一般是在晚上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, "2332362203o215223CY=2234377377377377377377377377"..., 4096, 4096) = 4096

pread(4, "2332372203o217,CY?,4377377377377377377377377"..., 4096, 12288) = 4096

pread(4, "2332372203o217,CY?,4377377377377377377377377"..., 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, " ", 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 from"..., 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 from"..., 97) = 97

close(8)                                = 0

write(1, "xtrabackup_logfile"..., 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, "273LOCK BINLOG FOR BACKUP", 27, 0, NULL, 0) = 27

sendto(3, "223SHOW SLAVE STATUS", 22, 0, NULL, 0) = 22

sendto(3, "173SHOW 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, "233SHOW 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, "%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, "163UNLOCK BINLOG", 18, 0, NULL, 0) = 18

sendto(3, "163UNLOCK TABLES", 18, 0, NULL, 0) = 18

recvfrom(3, "712", 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, " innobackupex: Backup created in"..., 50) = 50

write(2, "innobackupex: MySQL binlog posit"..., 85) = 85

write(2, "innobackupex: MySQL slave binlog"..., 119) = 119

sendto(3, "263SELECT 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/