每日MySQL之014：Point-in-Time recovery

mysqlbinlog可以使用start-datetime/stop-datetime选取某个时间段内的日志，或者start-position/stop-position选取某个log_pos范围内的日志。这一点可以用来做Point-in-Time recovery。

假定以下场景：在某个时刻，不小心插入了一条'name4'的记录，需要使用原来的备份+binary log实现Point-in-Time recovery

mysql> CREATE TABLE `B` ( `col1` char(15) DEFAULT NULL, `col2` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP);

shell> mysqldump -h localhost -u root -pqingsong test1 > test1.sql 

mysql> reset master;
mysql> insert into B values('name1', default);
mysql> insert into B values('name2', default);
mysql> insert into B values('name3', default);
mysql> insert into B values('name4', default); <--误操作,本不想插入这条数据的
mysql> insert into B values('name5', default);
mysql> select * from B;
+-------+---------------------+
| col1  | col2                |
+-------+---------------------+
| name1 | 2017-08-08 09:01:48 |
| name2 | 2017-08-08 09:01:53 |
| name3 | 2017-08-08 09:01:58 |
| name4 | 2017-08-08 09:02:03 |
| name5 | 2017-08-08 09:02:12 |
+-------+---------------------+
5 rows in set (0.00 sec)

1. 熟悉start-datetime/stop-datetime参数

先按照时间段读取binary log：
shell> mysqlbinlog /var/log/mysql/binerr.000001 > full
shell> mysqlbinlog --stop-datetime="2017-08-08 09:01:58" /var/log/mysql/binerr.000001 > part1
shell> mysqlbinlog --start-datetime="2017-08-08 09:01:58" /var/log/mysql/binerr.000001 > part2
shell> mysqlbinlog --start-datetime="2017-08-08 09:01:53" --stop-datetime="2017-08-08 09:02:03" /var/log/mysql/binerr.000001 > part3

full文件里包含了所有5条insert操作
root@db2a:~#   grep -i 'name[1-9]' -B 3 full | grep -iv -e 'SET TIMESTAMP' -e '^# at'
#170808  9:01:48 server id 1  end_log_pos 414 CRC32 0xbcd4fbfc  Query   thread_id=4     exec_time=0     error_code=0
use `test1`/*!*/;
insert into B values('name1', default)
--
#170808  9:01:53 server id 1  end_log_pos 705 CRC32 0x0521172a  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name2', default)
--
#170808  9:01:58 server id 1  end_log_pos 996 CRC32 0xe6269ccf  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name3', default)
--
#170808  9:02:03 server id 1  end_log_pos 1287 CRC32 0xc7bff093         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name4', default)
--
#170808  9:02:12 server id 1  end_log_pos 1578 CRC32 0x70d29d1e         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name5', default)

指定stop-datetime="2017-08-08 09:01:58"时，只读取了前两条记录：
root@db2a:~#  grep -i 'name[1-9]' -B 3 part1  | grep -iv -e 'SET TIMESTAMP' -e '^# at'
#170808  9:01:48 server id 1  end_log_pos 414 CRC32 0xbcd4fbfc  Query   thread_id=4     exec_time=0     error_code=0
use `test1`/*!*/;
insert into B values('name1', default)
--
#170808  9:01:53 server id 1  end_log_pos 705 CRC32 0x0521172a  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name2', default)

指定-start-datetime="2017-08-08 09:01:58" 时，读取了后三条记录：
root@db2a:~# grep -i 'name[1-9]' -B 3 part2  | grep -iv -e 'SET TIMESTAMP' -e '^# at'
#170808  9:01:58 server id 1  end_log_pos 996 CRC32 0xe6269ccf  Query   thread_id=4     exec_time=0     error_code=0
use `test1`/*!*/;
insert into B values('name3', default)
--
#170808  9:02:03 server id 1  end_log_pos 1287 CRC32 0xc7bff093         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name4', default)
--
#170808  9:02:12 server id 1  end_log_pos 1578 CRC32 0x70d29d1e         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name5', default)

指定"2017-08-08 09:01:53"到"2017-08-08 09:02:03"之间时，只有两条记录：
root@db2a:~# grep -i 'name[1-9]' -B 3 part3  | grep -iv -e 'SET TIMESTAMP' -e '^# at'
#170808  9:01:53 server id 1  end_log_pos 705 CRC32 0x0521172a  Query   thread_id=4     exec_time=0     error_code=0
use `test1`/*!*/;
insert into B values('name2', default)
--
#170808  9:01:58 server id 1  end_log_pos 996 CRC32 0xe6269ccf  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name3', default)

由上面可以看到start time是闭区间，而stop time是开区间，即[start-datetime, stop-datetime), 如果指定stop-datetime="2017-08-08 09:01:58"，实际上读取到"2017-08-08 09:01:57"

2. 根据start-datetime/stop-datetime做Point-in-Time Recovery

2.1 恢复到备份时刻
shell> mysqladmin -pqingsong flush-logs
shell> mysql -h localhost -u root -pqingsong test1 < test1.sql

2.2 恢复到name3
由于name4的插入时间为2017-08-08 09:02:03,加上stop-datetime是开区间，所以指定到这个时间即可：
shell> mysqlbinlog --stop-datetime="2017-08-08 09:02:03" /var/log/mysql/binerr.000001 | mysql -h localhost -u root -pqingsong test1
mysql> select * from B;
+-------+---------------------+
| col1  | col2                |
+-------+---------------------+
| name1 | 2017-08-08 09:01:48 |
| name2 | 2017-08-08 09:01:53 |
| name3 | 2017-08-08 09:01:58 |
+-------+---------------------+
3 rows in set (0.00 sec)

2.3 跳过name4
从name4的插入时间"2017-08-08 09:02:03"的下一秒开始：
shell> mysqlbinlog --start-datetime="2017-08-08 09:02:04"  /var/log/mysql/binerr.000001 | mysql -h localhost -u root -pqingsong test1
mysql> select * from B;
+-------+---------------------+
| col1  | col2                |
+-------+---------------------+
| name1 | 2017-08-08 09:01:48 |
| name2 | 2017-08-08 09:01:53 |
| name3 | 2017-08-08 09:01:58 |
| name5 | 2017-08-08 09:02:12 |
+-------+---------------------+
4 rows in set (0.00 sec)

3. 根据start-position/stop-position做Point-in-Time Recovery

设想一种场景，就是在同一时间内，做了很多的操作，只有一条操作是需要跳过的，那么这时候再根据时间段来做恢复就很困难了，这时候可以根据log position来做。上面已经看到，每条操作前都有一条类似于"# at 591"的记录，以及 "end_log_pos 705"。这里的591是指当前操作开始的位置，705是当前操作结束的位置+1（也就是下一个操作开始的位置）。查看整个log的内容，可以看到每条insert语句的开始、结束位置
shell> grep -i 'name[1-9]' -B 3 full | grep -iv -e 'SET TIMESTAMP'
#170808  9:01:48 server id 1   end_log_pos 414 CRC32 0xbcd4fbfc  Query   thread_id=4     exec_time=0     error_code=0
use `test1`/*!*/;
insert into B values('name1', default)
--
# at 591
#170808  9:01:53 server id 1   end_log_pos 705 CRC32 0x0521172a  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name2', default)
--
# at 882
#170808  9:01:58 server id 1   end_log_pos 996 CRC32 0xe6269ccf  Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name3', default)
--
# at 1173
#170808  9:02:03 server id 1   end_log_pos 1287 CRC32 0xc7bff093         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name4', default)
--
# at 1464
#170808  9:02:12 server id 1   end_log_pos 1578 CRC32 0x70d29d1e         Query   thread_id=4     exec_time=0     error_code=0
insert into B values('name5', default)

'name4'的start position是1173, 它下一个操作的start position是1287，所以，Point-in-Time recovery的时候，先做到1173，再从1287开始做，这样就跳过了'name4'
(这里的stop-position仍然是开区间)
shell> mysql -h localhost -u root -pqingsong test1 < test1.sql

shell> mysqlbinlog --stop-position=1173 /var/log/mysql/binerr.000001 | mysql -h localhost -u root -pqingsong test1

shell> mysqlbinlog --start-position=1287 /var/log/mysql/binerr.000001 | mysql -h localhost -u root -pqingsong test1

4. 补充说明

1. 如果事务涉及到多个日志，则不建议分开进行（涉及到临时表），建议的方法是，把日志条目写到文件里，然后修改文件，之后直接执行文件，如下：
shell> mysqlbinlog binlog.000001 >  /tmp/statements.sql
shell> mysqlbinlog binlog.000002 >> /tmp/statements.sql

shell> mysql -u root -p -e "source /tmp/statements.sql"

2. 除了mysqlbinlog之外，还有一个命令show binlog events 可以查看binary log中的事件，能够查询到每个event的Pos和End_log_pos如下：

mysql> show binlog events in 'binerr.000001';
+---------------+------+----------------+-----------+-------------+-----------------------------------------------------+
| Log_name      | Pos  | Event_type     | Server_id | End_log_pos | Info                                                |
+---------------+------+----------------+-----------+-------------+-----------------------------------------------------+
| binerr.000001 |    4 | Format_desc    |         1 |         123 | Server ver: 5.7.18-log, Binlog ver: 4               |
| binerr.000001 |  123 | Previous_gtids |         1 |         154 |                                                     |
| binerr.000001 |  154 | Anonymous_Gtid |         1 |         219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                |
| binerr.000001 |  219 | Query          |         1 |         300 | BEGIN                                               |
| binerr.000001 |  300 | Query          |         1 |         414 | use `test1`; insert into B values('name1', default) |
| binerr.000001 |  414 | Xid            |         1 |         445 | COMMIT /* xid=212 */                                |
| binerr.000001 |  445 | Anonymous_Gtid |         1 |         510 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                |
| binerr.000001 |  510 | Query          |         1 |         591 | BEGIN                                               |
| binerr.000001 |  591 | Query          |         1 |         705 | use `test1`; insert into B values('name2', default) |
| binerr.000001 |  705 | Xid            |         1 |         736 | COMMIT /* xid=213 */                                |
| binerr.000001 |  736 | Anonymous_Gtid |         1 |         801 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                |
| binerr.000001 |  801 | Query          |         1 |         882 | BEGIN                                               |
| binerr.000001 |  882 | Query          |         1 |         996 | use `test1`; insert into B values('name3', default) |
| binerr.000001 |  996 | Xid            |         1 |        1027 | COMMIT /* xid=214 */                                |
| binerr.000001 | 1027 | Anonymous_Gtid |         1 |        1092 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                |
| binerr.000001 | 1092 | Query          |         1 |        1173 | BEGIN                                               |
| binerr.000001 | 1173 | Query          |         1 |        1287 | use `test1`; insert into B values('name4', default) |
| binerr.000001 | 1287 | Xid            |         1 |        1318 | COMMIT /* xid=215 */                                |
| binerr.000001 | 1318 | Anonymous_Gtid |         1 |        1383 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                |
| binerr.000001 | 1383 | Query          |         1 |        1464 | BEGIN                                               |
| binerr.000001 | 1464 | Query          |         1 |        1578 | use `test1`; insert into B values('name5', default) |
| binerr.000001 | 1578 | Xid            |         1 |        1609 | COMMIT /* xid=216 */                                |
| binerr.000001 | 1609 | Rotate         |         1 |        1653 | binerr.000002;pos=4                                 |
+---------------+------+----------------+-----------+-------------+-----------------------------------------------------+
23 rows in set (0.00 sec)