利用xtrabackup和binlog增量恢复时提示表记录不存在案例

一.基本信息
版本：10.0.20-MariaDB-log
数据文件和redo log位置:/apps/dbdat/mariadb10_data3306/
bing log位置：/apps/dbdat/mariadb10_data3306/log
主机信息:mvxl0784 10.16.24.109
配置文件：/apps/dbdat/mariadb10_data3306/my3306.cnf

二.问题背景及描述
   利用xtrabackup工具在2016-05-17 01:11:55时间点的全备加上binlog增量恢复mysql到2016年5月18日0点。
我们查看备份集中的xtrabackup_info和xtrabackup_binlog_info文件
cat xtrabackup_info
start_time = 2016-05-17 01:00:01
end_time = 2016-05-17 01:11:55
lock_time = 2
binlog_pos = filename 'mysql-bin.000271', position 291755824, GTID of the last change '0-19873306-348307239'

cat xtrabackup_binlog_info
mysql-bin.000271        291755824       0-19873306-348307239

从上面看到，备份开始时间为2016-05-17 01:00:01，完成时间为2016-05-17 01:11:55，对应的的binlog为mysql-bin.000271，position为291755824。

正常执行完xtrabckup的全备恢复后，对以下binlog文件进行增量恢复，binlog文件如下：
[apps@mvxl0784 backup]$ ls -ltr
total 3751088
-rw-r----- 1 apps apps  536871119 May 18 09:37 mysql-bin.000271
-rw-r----- 1 apps apps  536871210 May 18 09:37 mysql-bin.000272
drwxr-xr-x 8 apps apps       4096 May 18 10:03 xtrabackup_20160517010001

先执行了第一个binlog增量恢复是没问题：
[apps@mvxl0784 backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-datetime='2016-05-17 01:11:55'|/apps/svr/mariadb10/bin/mysql -u root -

psafe2016 --socket=/tmp/mysql3306.sock
real    1m13.570s
user    0m19.412s
sys     0m10.718s
接着对第二个binlog文件再执行时报错，显示找不到表t_task_log的记录:
[apps@mvxl0784 backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000272 --stop-datetime='2016-05-18 00:00:00'|/apps/svr/mariadb10/bin/mysql -u root -

psafe2016 --socket=/tmp/mysql3306.sock
ERROR 1032 (HY000) at line 165805: Can't find record in 't_task_log'

三.问题分析
   针对上面报错，显示在binlog日志解析的165805行，我们看下165805行及附件日志是什么操作：
165783  # at 1746660
165784  #160517  9:29:50 server id 19873306  end_log_pos 1746698        GTID 0-19873306-348602810
165785  /*!100001 SET @@session.gtid_seq_no=348602810*//*!*/;
165786  BEGIN
165787  /*!*/;
165788  # at 1746698
165789  # at 1746764
165790  #160517  9:29:50 server id 19873306  end_log_pos 1746764        Table_map: `lots`.`t_tracking_log` mapped to number 227
165791  #160517  9:29:50 server id 19873306  end_log_pos 1746839        Write_rows: table id 227 flags: STMT_END_F
165792  ### INSERT INTO `lots`.`t_tracking_log`
165793  ### SET
165794  ###   @1=31757386 /* INT meta=0 nullable=0 is_null=0 */
165795  ###   @2=NULL /* INT meta=0 nullable=1 is_null=1 */
165796  ###   @3='AD16051501234897' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
165797  ###   @4='2016-05-17 09:29:51.245' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
165798  ###   @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
165799  ###   @6=NULL /* VARSTRING(150) meta=6000 nullable=1 is_null=1 */
165800  # at 1746839
165801  #160517  9:29:50 server id 19873306  end_log_pos 1746866        Xid = 78680652
165802  COMMIT/*!*/;
165803  # at 1746866
165804  #160517  9:29:50 server id 19873306  end_log_pos 1746904        GTID 0-19873306-348602811
165805  /*!100001 SET @@session.gtid_seq_no=348602811*//*!*/;
165806  BEGIN
165807  /*!*/;
165808  # at 1746904
165809  # at 1746996
165810  #160517  9:29:50 server id 19873306  end_log_pos 1746996        Table_map: `lots`.`t_carrier_tracking` mapped to number 226
165811  #160517  9:29:50 server id 19873306  end_log_pos 1747217        Write_rows: table id 226 flags: STMT_END_F
165812  ### INSERT INTO `lots`.`t_carrier_tracking`
165813  ### SET
............................................
...............................................

上面165805行及附近日志都没有与表t_task_log相关的操作，怪事真多啊。

查看错误日志的最后部分显示如下：
Version: '10.0.20-MariaDB-log'  socket: '/tmp/mysql3306.sock'  port: 3306  MariaDB Server
160518 16:21:57 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table lots.t_task_log; Can't find record in 't_task_log
', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 2459743, Internal MariaDB error c
ode: 1032

原来找不到表记录发生的位置是在binlog中的2459743。然后再通过分析binlog，找到2459743位置所发生的事务操作如下：
# at 2459207
#160517  9:30:00 server id 19873306  end_log_pos 2459245        GTID 0-19873306-348605082
/*!100001 SET @@session.gtid_seq_no=348605082*//*!*/;
BEGIN
/*!*/;
# at 2459245
# at 2459311
#160517  9:30:00 server id 19873306  end_log_pos 2459311        Table_map: `lots`.`t_task_log` mapped to number 233
#160517  9:30:00 server id 19873306  end_log_pos 2459743        Update_rows: table id 233 flags: STMT_END_F
### UPDATE `lots`.`t_task_log`
### WHERE
###   @1=369680 /* INT meta=0 nullable=0 is_null=0 */
###   @2=21 /* INT meta=0 nullable=1 is_null=0 */
###   @3='HTKYQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
###   @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
###   @7=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
###   @8=NULL /* DATETIME meta=15000 nullable=1 is_null=1 */
###   @9=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
### SET
###   @1=369680 /* INT meta=0 nullable=0 is_null=0 */
###   @2=21 /* INT meta=0 nullable=1 is_null=0 */
###   @3='HTKYQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @5='success' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
###   @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
###   @7=300821 /* INT meta=0 nullable=1 is_null=0 */
###   @8='任务ID：21，名称：HTKYQueryCarrierTrackingJob，任务触发器：Express.HTKYQueryCarrierTrackingJob，任务开始执行......任务执行
成功！，执行耗时：300821ms，开始时间：2016-05-17 09:25:00，结束时间：2016-05-17 09:30:01' /* VARSTRING(15000) meta=15000 nullable=1
is_null=0 */
###   @9=2016-05-17 09:30:01 /* DATETIME meta=0 nullable=1 is_null=0 */
# at 2459743
#160517  9:30:00 server id 19873306  end_log_pos 2459770        Xid = 78694692
COMMIT/*!*/;
# at 2459770

查看表t_task_log的定义：
 show create table t_task_log\G
*************************** 1. row ***************************
       Table: t_task_log
Create Table: CREATE TABLE `t_task_log` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `job_id` int(11) DEFAULT NULL COMMENT '任务ID',
  `job_name` varchar(50) DEFAULT NULL COMMENT '任务名称',
  `cron_expression` varchar(50) DEFAULT NULL COMMENT 'cron表达式',
  `execution_status` varchar(10) DEFAULT NULL COMMENT '执行状态 success|error',
  `execution_date` datetime DEFAULT NULL COMMENT '执行时间',
  `execution_time` int(11) DEFAULT NULL COMMENT '执行耗时',
  `description` varchar(5000) DEFAULT NULL COMMENT '描述',
  `end_date` datetime DEFAULT NULL COMMENT '结束时间',
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=369694 DEFAULT CHARSET=utf8 COMMENT='JOB任务执行记录日志'
1 row in set (0.02 sec)

查询execution_date字段值为2016-05-17 09:25:00的记录，是否存在，下面返回为空，确认表记录不存在的原因是因为第一个binlog恢复应用到库中时执行有异常。
(product)root@localhost [lots]> select execution_status,execution_time,end_date  from `lots`.`t_task_log` where execution_date='2016-05-17 09:25:00';
Empty set (4.83 sec)
在对第一个binlog恢复时，没有看到报错，如是重新再来恢复一次，这次将--start-datetime参数改为--start-position，并开启genaral_log。
time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-position=291755824|/apps/svr/mariadb10/bin/mysql -u root -psafe2016 --socket=/tmp/mysql3306.sock
ERROR 2006 (HY000) at line 3634523: MySQL server has gone away
real    1m14.251s
user    0m18.285s
sys     0m10.723s

先看错误日志，错误日志显示没有报错：

160519  9:51:31 [Note] InnoDB: Using mutexes to ref count buffer pool pages
160519  9:51:31 [Note] InnoDB: The InnoDB memory heap is disabled
160519  9:51:31 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
160519  9:51:31 [Note] InnoDB: Memory barrier is not used
160519  9:51:31 [Note] InnoDB: Compressed tables use zlib 1.2.3
160519  9:51:31 [Note] InnoDB: Using Linux native AIO
160519  9:51:31 [Note] InnoDB: Using CPU crc32 instructions
160519  9:51:31 [Note] InnoDB: Initializing buffer pool, size = 21.0G
160519  9:51:32 [Note] InnoDB: Completed initialization of buffer pool
160519  9:51:32 [Note] InnoDB: Highest supported file format is Barracuda.
160519  9:51:34 [Note] InnoDB: 128 rollback segment(s) are active.
160519  9:51:34 [Note] InnoDB: Waiting for purge to start
160519  9:51:34 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 377271951224
160519  9:51:34 [Note] Plugin 'FEEDBACK' is disabled.
160519  9:51:34 [Note] Server socket created on IP: '0.0.0.0'.
160519  9:51:34 [Note] Event Scheduler: Loaded 0 events
160519  9:51:34 [Note] Event Scheduler: scheduler thread started with id 2
160519  9:51:34 [Note] /apps/svr/mariadb10/bin/mysqld: ready for connections.
Version: '10.0.20-MariaDB-log'  socket: '/tmp/mysql3306.sock'  port: 3307  MariaDB Server

看一般日志最后显示几行：
160519 10:02:48     6 Query     /*!100001 SET @@session.gtid_seq_no=348475348*/
                    6 Query     BEGIN

一般日志显示，在准备执行gtid为348475348的事务时，与mysql没有交互信息了，说明从lsn 348475348 开始binlog就没有执行恢复应用到库中。

我们通过execution_date字段值为2016-05-17 09:25:00的记录，查找这条记录是在binlog中什么位置插入的，如下显示是lsn 348528548这条事务。
# at 515432241
#160517  9:24:59 server id 19873306  end_log_pos 515432279      GTID 0-19873306-348528548
/*!100001 SET @@session.gtid_seq_no=348528548*//*!*/;
BEGIN
/*!*/;
# at 515432279
# at 515432345
#160517  9:24:59 server id 19873306  end_log_pos 515432345      Table_map: `lots`.`t_task_log` mapped to number 233
#160517  9:24:59 server id 19873306  end_log_pos 515432435      Write_rows: table id 233 flags: STMT_END_F
### INSERT INTO `lots`.`t_task_log`
### SET
###   @1=369677 /* INT meta=0 nullable=0 is_null=0 */
###   @2=25 /* INT meta=0 nullable=1 is_null=0 */
###   @3='TTKQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
###   @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
###   @7=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
###   @8=NULL /* DATETIME meta=15000 nullable=1 is_null=1 */
###   @9=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
# at 515432435
#160517  9:24:59 server id 19873306  end_log_pos 515432462      Xid = 78203609
COMMIT/*!*/;
# at 515432462

上面的原因搞清了，回到原来报错：ERROR 2006 (HY000)，从网上查找显示，批量数据操作和执行时该报错与下面参数设置有关，我们检查一下以下三个参数大小：
max_allowed_packet=64m
interactive_timeout=120
wait_timeout=120

四.问题解决

   把上面值分别调整为：
max_allowed_packet=200m
interactive_timeout=600
wait_timeout=600
重新再做一次前面步骤(当然接着报错位置开始增量恢复也行):
[apps@mvxl0784 backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-position=291755824|/apps/svr/mariadb10/bin/mysql -u root -psafe2016 --

socket=/tmp/mysql3306.sock

real    3m15.437s
user    0m28.510s
sys     0m18.515s
[apps@mvxl0784 backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000272 --stop-datetime='2016-05-18 00:00:00'|/apps/svr/mariadb10/bin/mysql -u root -

psafe2016 --socket=/tmp/mysql3306.sock

real    7m2.584s
user    1m40.549s
sys     1m8.097s
查看上面找不到表记录的位置的SQL执行情况，可以正常返回值，说明有成功恢复。
(product)root@localhost [(none)]> select execution_status,execution_time,end_date  from `lots`.`t_task_log` where execution_date='2016-05-17 09:25:00';
+------------------+----------------+---------------------+
| execution_status | execution_time | end_date            |
+------------------+----------------+---------------------+
| success          |         218239 | 2016-05-17 09:28:38 |
| success          |         859612 | 2016-05-17 09:39:19 |
| success          |         519037 | 2016-05-17 09:33:39 |
| success          |           9845 | 2016-05-17 09:25:10 |
| success          |         528138 | 2016-05-17 09:33:48 |
| success          |         300821 | 2016-05-17 09:30:01 |
| success          |         528493 | 2016-05-17 09:33:48 |
+------------------+----------------+---------------------+
7 rows in set (6.50 sec)

问题到此已解决了。

五.--start-datetime不报错，而--start-position有报错？
针对这个问题，后面我又重新做了一次恢复，实际上同样也会报错，估计是当时没有看清楚或copy信息时漏掉了，自己坑自己了，折腾好几次。
[apps@mvxl0784 backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-datetime='2016-05-17 01:11:55'|/apps/svr/mariadb10/bin/mysql -u root -

psafe2016 --socket=/tmp/mysql3306.sock
ERROR 2006 (HY000) at line 3634523: MySQL server has gone away

real    1m6.817s
user    0m18.507s
sys     0m9.851s

不要放过任何命令返回信息，特别是报错信息!