MySQL 闪回工具之 binlog2sql

生产上误删数据、误改数据的现象也是时常发生的现象，作为 DBA 这时候就需要出来补锅了，最开始的做法是恢复备份，然后从中找到需要的数据再进行修复，但是这个时间太长了，对于大表少数数据的修复来讲，动作太大，成本也大。当然还有其他的一些操作方法，这里暂不展开来讲，我们今天有主角。

最近有些朋友在用大众点评开源的一个 MySQL 闪回工具 -- binlog2sql，因此也测试了一把，一探究竟。

用途

• 数据回滚
• 主从切换后数据不一致的修复
• 从 binlog 生成标准 SQL，带来的衍生功能

闪回原理简析

开始之前，先说说闪回。我们都知道 MySQL binlog 以 event 为单位，记录数据库的变更信息，这些信息能够帮助我们重现这之间的所有变化，也就是所谓的闪回。

binlog 有三种可选的格式：

• statement：基于 SQL 语句的模式，binlog 数据量小，但是某些语句和函数在复制过程可能导致数据不一致甚至出错；
• mixed：混合模式，根据语句来选用是 statement 还是 row 模式；
• row：基于行的模式，记录的是行的完整变化。安全，但 binlog 会比其他两种模式大很多；

利用 binlog 做闪回，需要将 binlog 格式设置为 row，因为我们需要最详尽的信息来确定操作之后数据不会出错。

既然 binlog 以 event 形式记录了所有的变更信息，那么我们把需要回滚的 event，从后往前回滚回去即可。

回滚操作：

• 对于 delete 操作，我们从 binlog 提取出 delete 信息，反向生成 insert 回滚语句；
• 对于 insert 操作，反向生成 delete 回滚语句；
• 对于 update 操作，根据信息生成反向的 update 语句；

准备

本次测试使用社区版 MySQL 5.7.17，binlog 格式设置为 row。

• 初始化测试表

root@localhost 14:57:35 [glonho]>CREATE TABLE `test` (
    ->   `id` int(11) NOT NULL AUTO_INCREMENT,
    ->   `name` varchar(20) NOT NULL,
    ->   `create_time` datetime NOT NULL,
    ->   PRIMARY KEY (`id`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;

Query OK, 0 rows affected (0.16 sec)

root@localhost 15:02:06 [glonho]>insert into test (name,create_time) values ('Glon Ho','2012-10-1'),('Eason Chan', '2016-05-02'),('Jacky Cheung', '2015-05-02');
Query OK, 3 rows affected (0.05 sec)
Records: 3  Duplicates: 0  Warnings: 0

root@localhost 15:02:23 [glonho]>select * from test;
+----+--------------+---------------------+
| id | name         | create_time         |
+----+--------------+---------------------+
|  1 | Glon Ho      | 2012-10-01 00:00:00 |
|  2 | Eason Chan   | 2016-05-02 00:00:00 |
|  3 | Jacky Cheung | 2015-05-02 00:00:00 |
+----+--------------+---------------------+
3 rows in set (0.00 sec)

• 查看闪回操作账号的权限信息

root@localhost 15:02:24 [glonho]>show grants for 'glon'@'%';
+--------------------------------------------------------------------------+
| Grants for glon@%                                                        |
+--------------------------------------------------------------------------+
| GRANT SELECT, REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'glon'@'%' |
+--------------------------------------------------------------------------+
1 row in set (0.00 sec)

开始

这一部分，主要测试 DML，也就是 delete、update、insert 等操作的闪回效果。

本次实验，更改一条数据，并删除一条数据，然后从解析 binlog 信息，到使用 binlog2sql 工具来生成标准和回滚 SQL，来剖析整个运行过程。

• 进行 update 和 delete 操作

root@localhost 15:02:29 [glonho]>update test set create_time = '2017-05-12' where name = 'Glon Ho';
Query OK, 1 row affected (0.05 sec)
Rows matched: 1  Changed: 1  Warnings: 0

root@localhost 15:03:34 [glonho]>select * from test;
+----+--------------+---------------------+
| id | name         | create_time         |
+----+--------------+---------------------+
|  1 | Glon Ho      | 2017-05-12 00:00:00 |
|  2 | Eason Chan   | 2016-05-02 00:00:00 |
|  3 | Jacky Cheung | 2015-05-02 00:00:00 |
+----+--------------+---------------------+
3 rows in set (0.00 sec)

root@localhost 15:03:40 [glonho]>delete from test where name = 'Jacky Cheung';
Query OK, 1 row affected (0.01 sec)

root@localhost 15:04:03 [glonho]>select * from test;
+----+------------+---------------------+
| id | name       | create_time         |
+----+------------+---------------------+
|  1 | Glon Ho    | 2017-05-12 00:00:00 |
|  2 | Eason Chan | 2016-05-02 00:00:00 |
+----+------------+---------------------+
2 rows in set (0.00 sec)

操作时候，Glon Ho 的时间改变了，而 Jacky Cheung 也被删除了。

• 查看当前 binlog 信息

root@localhost 15:04:04 [glonho]>show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000001 |     1381 |              |                  | 1e9269cb-3630-11e7-b892-080027d27daf:1-4 |
+------------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

• 使用 mysqlbinlog 解析 binlog 日志

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170512 14:57:35 server id 1003306  end_log_pos 123 CRC32 0xcd69513c 	Start: binlog v 4, server v 5.7.17-log created 170512 14:57:35 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 123
#170512 14:57:35 server id 1003306  end_log_pos 154 CRC32 0xd38f365b 	Previous-GTIDs
# [empty]
# at 154
#170512 15:02:06 server id 1003306  end_log_pos 219 CRC32 0xd50d9707 	GTID	last_committed=0	sequence_number=1
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:1'/*!*/;
# at 219
#170512 15:02:06 server id 1003306  end_log_pos 482 CRC32 0xa6491181 	Query	thread_id=4	exec_time=0	error_code=0
use `glonho`/*!*/;
SET TIMESTAMP=1494572526/*!*/;
SET @@session.pseudo_thread_id=4/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE `test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(20) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
/*!*/;
# at 482
#170512 15:02:23 server id 1003306  end_log_pos 547 CRC32 0xeb55009b 	GTID	last_committed=1	sequence_number=2
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:2'/*!*/;
# at 547
#170512 15:02:23 server id 1003306  end_log_pos 621 CRC32 0x2edf4f1a 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1494572543/*!*/;
BEGIN
/*!*/;
# at 621
#170512 15:02:23 server id 1003306  end_log_pos 675 CRC32 0x48915eb3 	Table_map: `glonho`.`test` mapped to number 219
# at 675
#170512 15:02:23 server id 1003306  end_log_pos 772 CRC32 0xea1b47e6 	Write_rows: table id 219 flags: STMT_END_F
### INSERT INTO `glonho`.`test`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Glon Ho' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2012-10-01 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### INSERT INTO `glonho`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Eason Chan' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2016-05-02 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### INSERT INTO `glonho`.`test`
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Jacky Cheung' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2015-05-02 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 772
#170512 15:02:23 server id 1003306  end_log_pos 803 CRC32 0x35bf5664 	Xid = 14
COMMIT/*!*/;
# at 803
#170512 15:03:34 server id 1003306  end_log_pos 868 CRC32 0x3f830a6e 	GTID	last_committed=2	sequence_number=3
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:3'/*!*/;
# at 868
#170512 15:03:34 server id 1003306  end_log_pos 942 CRC32 0x35d2d23c 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1494572614/*!*/;
BEGIN
/*!*/;
# at 942
#170512 15:03:34 server id 1003306  end_log_pos 996 CRC32 0x56346189 	Table_map: `glonho`.`test` mapped to number 219
# at 996
#170512 15:03:34 server id 1003306  end_log_pos 1068 CRC32 0xcb2187c2 	Update_rows: table id 219 flags: STMT_END_F
### UPDATE `glonho`.`test`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Glon Ho' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2012-10-01 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Glon Ho' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2017-05-12 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 1068
#170512 15:03:34 server id 1003306  end_log_pos 1099 CRC32 0xbc8b6f9d 	Xid = 16
COMMIT/*!*/;
# at 1099
#170512 15:04:03 server id 1003306  end_log_pos 1164 CRC32 0x203853e1 	GTID	last_committed=3	sequence_number=4
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:4'/*!*/;
# at 1164
#170512 15:04:03 server id 1003306  end_log_pos 1238 CRC32 0xde9d2f56 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1494572643/*!*/;
BEGIN
/*!*/;
# at 1238
#170512 15:04:03 server id 1003306  end_log_pos 1292 CRC32 0xd6950fe2 	Table_map: `glonho`.`test` mapped to number 219
# at 1292
#170512 15:04:03 server id 1003306  end_log_pos 1350 CRC32 0xbe57572b 	Delete_rows: table id 219 flags: STMT_END_F
### DELETE FROM `glonho`.`test`
### WHERE
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Jacky Cheung' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2015-05-02 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 1350
#170512 15:04:03 server id 1003306  end_log_pos 1381 CRC32 0x96e3ba93 	Xid = 18
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

解析 binlog 只是展示一下这些操作在日志中记录的样子，不叙说如何具体地根据 binlog 信息来进行闪回操作。

- 使用 binlog2sql 工具

1) 解析出标准SQL

直接整个解析 mysql-bin.000001 日志

[root@node1 binlog2sql]# python binlog2sql.py -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001'
USE glonho;
CREATE TABLE `test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(20) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2012-10-01 00:00:00', 1, 'Glon Ho'); #start 547 end 772 time 2017-05-12 15:02:23
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2016-05-02 00:00:00', 2, 'Eason Chan'); #start 547 end 772 time 2017-05-12 15:02:23
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2015-05-02 00:00:00', 3, 'Jacky Cheung'); #start 547 end 772 time 2017-05-12 15:02:23
UPDATE `glonho`.`test` SET `create_time`='2017-05-12 00:00:00', `id`=1, `name`='Glon Ho' WHERE `create_time`='2012-10-01 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 868 end 1068 time 2017-05-12 15:03:34
DELETE FROM `glonho`.`test` WHERE `create_time`='2015-05-02 00:00:00' AND `id`=3 AND `name`='Jacky Cheung' LIMIT 1; #start 1164 end 1350 time 2017-05-12 15:04:03

可以看到，几乎完美重现了我们上面执行过的 SQL，而且生成的每个 SQL 后面都带有该语句在 binlog 中的 position 信息和该语句的执行时间。

2) 解析出回滚SQL

生产从建表，到数据的更新删除，这个时间端内的操作的回滚语句：

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-datetime="2017-05-12 14:57:00" --stop-datetime="2017-05-12 15:04:22"
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2015-05-02 00:00:00', 3, 'Jacky Cheung'); #start 1164 end 1350 time 2017-05-12 15:04:03
UPDATE `glonho`.`test` SET `create_time`='2012-10-01 00:00:00', `id`=1, `name`='Glon Ho' WHERE `create_time`='2017-05-12 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 868 end 1068 time 2017-05-12 15:03:34
DELETE FROM `glonho`.`test` WHERE `create_time`='2015-05-02 00:00:00' AND `id`=3 AND `name`='Jacky Cheung' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2016-05-02 00:00:00' AND `id`=2 AND `name`='Eason Chan' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2012-10-01 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23

可以看到，建表语句属于 DDL，没有生产回滚操作，即使在 binlog 中记录了该 SQL；初始化时批量插入的 3 条数据，则被分成了 3 条 delete 语句；更新 Glon Ho 的时间列的语句也被反向生成出来了，set 和 where 的列掉转过来了；而删除 Jacky Cheung 的语句生成了一条 insert 语句。

这和上面闪回原理中回滚操作说的是一致的。

• 下面对回滚时间进行细粒度的操作，具体到某一个 event

通过根据 mysqlbinlog 解析出来的日志信息，使用 binlog2sql 来获得回滚的 SQL 语句：

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=547 --stop-position=803
DELETE FROM `glonho`.`test` WHERE `create_time`='2015-05-02 00:00:00' AND `id`=3 AND `name`='Jacky Cheung' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2016-05-02 00:00:00' AND `id`=2 AND `name`='Eason Chan' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2012-10-01 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
[root@node1 binlog2sql]# 

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=868 --stop-position=1099
UPDATE `glonho`.`test` SET `create_time`='2012-10-01 00:00:00', `id`=1, `name`='Glon Ho' WHERE `create_time`='2017-05-12 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 868 end 1068 time 2017-05-12 15:03:34
[root@node1 binlog2sql]# 

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=1164 --stop-position=1350
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2015-05-02 00:00:00', 3, 'Jacky Cheung'); #start 1164 end 1350 time 2017-05-12 15:04:03
[root@node1 binlog2sql]# 

根据通过 binlog2sql 解析出来指定时间段的数据获取到日志信息，使用 binlog2sql 来获得具体回滚的 SQL 语句：

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=547 --stop-position=772
DELETE FROM `glonho`.`test` WHERE `create_time`='2015-05-02 00:00:00' AND `id`=3 AND `name`='Jacky Cheung' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2016-05-02 00:00:00' AND `id`=2 AND `name`='Eason Chan' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
DELETE FROM `glonho`.`test` WHERE `create_time`='2012-10-01 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 547 end 772 time 2017-05-12 15:02:23
[root@node1 binlog2sql]# 

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=868 --stop-position=1068
UPDATE `glonho`.`test` SET `create_time`='2012-10-01 00:00:00', `id`=1, `name`='Glon Ho' WHERE `create_time`='2017-05-12 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 868 end 1068 time 2017-05-12 15:03:34
[root@node1 binlog2sql]# 

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-position=1164 --stop-position=1350
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2015-05-02 00:00:00', 3, 'Jacky Cheung'); #start 1164 end 1350 time 2017-05-12 15:04:03
[root@node1 binlog2sql]#

可以看到，这两种binlog pos 都解析出来正确的语句，尽管根据 mysqlbinlog 解析出来的日志信息是最准确的，而通过 binlog2sql 解析出来的指定时间段的数据获取到的日志信息在我们看来是不正确的，或者说是不完整的。

继续

下面我们再测试一下批量 delete 和 truncate，及 drop table 的情况

root@localhost 15:55:41 [glonho]>select * from test;
+----+------------+---------------------+
| id | name       | create_time         |
+----+------------+---------------------+
|  1 | Glon Ho    | 2017-05-12 00:00:00 |
|  2 | Eason Chan | 2016-05-02 00:00:00 |
+----+------------+---------------------+
2 rows in set (0.00 sec)

root@localhost 15:55:48 [glonho]>delete from test where id < 3;
Query OK, 2 rows affected (0.06 sec)

root@localhost 15:56:01 [glonho]>select * from test;
Empty set (0.00 sec)

root@localhost 15:56:03 [glonho]>insert into test (name,create_time) values ('Glon Ho','2012-10-1');
Query OK, 1 row affected (0.01 sec)

root@localhost 15:56:26 [glonho]>select * from test;
+----+---------+---------------------+
| id | name    | create_time         |
+----+---------+---------------------+
|  4 | Glon Ho | 2012-10-01 00:00:00 |
+----+---------+---------------------+
1 row in set (0.00 sec)

root@localhost 15:56:37 [glonho]>truncate table test;
Query OK, 0 rows affected (0.04 sec)

root@localhost 15:56:43 [glonho]>select * from test;
Empty set (0.00 sec)

root@localhost 15:56:47 [glonho]>drop table test;
Query OK, 0 rows affected (0.01 sec)

root@localhost 15:56:53 [glonho]>show tables;
Empty set (0.00 sec)

root@localhost 15:56:56 [glonho]>show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000001 |     2295 |              |                  | 1e9269cb-3630-11e7-b892-080027d27daf:1-8 |
+------------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

• 继续解析 binlog

解析新一轮操作生产的 binlog：

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170512 14:57:35 server id 1003306  end_log_pos 123 CRC32 0xcd69513c 	Start: binlog v 4, server v 5.7.17-log created 170512 14:57:35 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 1381
#170512 15:56:01 server id 1003306  end_log_pos 1446 CRC32 0x29eeeb58 	GTID	last_committed=4	sequence_number=5
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:5'/*!*/;
# at 1446
#170512 15:56:01 server id 1003306  end_log_pos 1520 CRC32 0x397feed7 	Query	thread_id=26	exec_time=0	error_code=0
SET TIMESTAMP=1494575761/*!*/;
SET @@session.pseudo_thread_id=26/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 1520
#170512 15:56:01 server id 1003306  end_log_pos 1574 CRC32 0xe1b822b7 	Table_map: `glonho`.`test` mapped to number 219
# at 1574
#170512 15:56:01 server id 1003306  end_log_pos 1648 CRC32 0xec210617 	Delete_rows: table id 219 flags: STMT_END_F
### DELETE FROM `glonho`.`test`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Glon Ho' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2017-05-12 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### DELETE FROM `glonho`.`test`
### WHERE
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Eason Chan' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2016-05-02 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 1648
#170512 15:56:01 server id 1003306  end_log_pos 1679 CRC32 0x8506ab3c 	Xid = 106
COMMIT/*!*/;
# at 1679
#170512 15:56:26 server id 1003306  end_log_pos 1744 CRC32 0x06d317f7 	GTID	last_committed=5	sequence_number=6
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:6'/*!*/;
# at 1744
#170512 15:56:26 server id 1003306  end_log_pos 1818 CRC32 0x06b90ae3 	Query	thread_id=26	exec_time=0	error_code=0
SET TIMESTAMP=1494575786/*!*/;
BEGIN
/*!*/;
# at 1818
#170512 15:56:26 server id 1003306  end_log_pos 1872 CRC32 0xea37392b 	Table_map: `glonho`.`test` mapped to number 219
# at 1872
#170512 15:56:26 server id 1003306  end_log_pos 1925 CRC32 0x7117bf7c 	Write_rows: table id 219 flags: STMT_END_F
### INSERT INTO `glonho`.`test`
### SET
###   @1=4 /* INT meta=0 nullable=0 is_null=0 */
###   @2='Glon Ho' /* VARSTRING(60) meta=60 nullable=0 is_null=0 */
###   @3='2012-10-01 00:00:00' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 1925
#170512 15:56:26 server id 1003306  end_log_pos 1956 CRC32 0x8f283ebd 	Xid = 108
COMMIT/*!*/;
# at 1956
#170512 15:56:43 server id 1003306  end_log_pos 2021 CRC32 0x9eeda351 	GTID	last_committed=6	sequence_number=7
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:7'/*!*/;
# at 2021
#170512 15:56:43 server id 1003306  end_log_pos 2109 CRC32 0xf447fce8 	Query	thread_id=26	exec_time=0	error_code=0
use `glonho`/*!*/;
SET TIMESTAMP=1494575803/*!*/;
truncate table test
/*!*/;
# at 2109
#170512 15:56:53 server id 1003306  end_log_pos 2174 CRC32 0xd9d80941 	GTID	last_committed=7	sequence_number=8
SET @@SESSION.GTID_NEXT= '1e9269cb-3630-11e7-b892-080027d27daf:8'/*!*/;
# at 2174
#170512 15:56:53 server id 1003306  end_log_pos 2295 CRC32 0xbb004dff 	Query	thread_id=26	exec_time=0	error_code=0
SET TIMESTAMP=1494575813/*!*/;
DROP TABLE `test` /* generated by server */
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

• 使用 binlog2sql 解析

1) 解析出标准SQL

解析出新一轮操作的 SQL：

[root@node1 binlog2sql]# python binlog2sql.py -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-datetime="2017-05-12 15:55:41"  --stop-datetime="2017-05-12 15:56:56" --start-file='mysql-bin.000001'
USE glonho;
truncate table test;
USE glonho;
DROP TABLE `test` /* generated by server */;

[root@node1 binlog2sql]# python binlog2sql.py -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-datetime="2017-05-12 15:55:41" --start-file='mysql-bin.000001'
USE glonho;
truncate table test;
USE glonho;
DROP TABLE `test` /* generated by server */;

[root@node1 binlog2sql]# python binlog2sql.py -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001'
USE glonho;
CREATE TABLE `test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(20) NOT NULL,
  `create_time` datetime NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
USE glonho;
truncate table test;
USE glonho;
DROP TABLE `test` /* generated by server */;

可以看到，尽管不断放宽解析的时间段，这一轮的批量 delete 和 insert 操作并没有被解析出来。

2) 解析出回滚SQL

在来看看回滚的 SQL 能否被解析出来：

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-datetime="2017-05-12 15:55:41"  --stop-datetime="2017-05-12 15:56:56"
[root@node1 binlog2sql]# 

很明显，解析不出来，失败了。

这就比较纳闷了，怎么会解析不出来呢，明明已经记录到 binlog 中了。

不急，我们再回头看看，binlog2sql 这个工具的操作是指定了 database 和 table 的，而此时我们已经把 table drop 掉了，所以导致解析不出来。

是不是这个原因呢？我们重新创建这张表，然后再看：

root@localhost 16:06:48 [glonho]>CREATE TABLE `test` (
    ->   `id` int(11) NOT NULL AUTO_INCREMENT,
    ->   `name` varchar(20) NOT NULL,
    ->   `create_time` datetime NOT NULL,
    ->   PRIMARY KEY (`id`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.05 sec)

重新解析出标准SQL：

[root@node1 binlog2sql]# python binlog2sql.py -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-datetime="2017-05-12 15:55:41"  --stop-datetime="2017-05-12 16:06:48" --start-file='mysql-bin.000001'
DELETE FROM `glonho`.`test` WHERE `create_time`='2017-05-12 00:00:00' AND `id`=1 AND `name`='Glon Ho' LIMIT 1; #start 1446 end 1648 time 2017-05-12 15:56:01
DELETE FROM `glonho`.`test` WHERE `create_time`='2016-05-02 00:00:00' AND `id`=2 AND `name`='Eason Chan' LIMIT 1; #start 1446 end 1648 time 2017-05-12 15:56:01
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2012-10-01 00:00:00', 4, 'Glon Ho'); #start 1744 end 1925 time 2017-05-12 15:56:26
USE glonho;
truncate table test;
USE glonho;
DROP TABLE `test` /* generated by server */;
[root@node1 binlog2sql]# 

再次解析出回滚SQL：

[root@node1 binlog2sql]# python binlog2sql.py --flashback -h127.0.0.1 -P3306 -uglon -p'123456' -dglonho -ttest --start-file='mysql-bin.000001' --start-datetime="2017-05-12 15:55:41" --stop-datetime="2017-05-12 16:06:48"
DELETE FROM `glonho`.`test` WHERE `create_time`='2012-10-01 00:00:00' AND `id`=4 AND `name`='Glon Ho' LIMIT 1; #start 1744 end 1925 time 2017-05-12 15:56:26
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2016-05-02 00:00:00', 2, 'Eason Chan'); #start 1446 end 1648 time 2017-05-12 15:56:01
INSERT INTO `glonho`.`test`(`create_time`, `id`, `name`) VALUES ('2017-05-12 00:00:00', 1, 'Glon Ho'); #start 1446 end 1648 time 2017-05-12 15:56:01
[root@node1 binlog2sql]# 

可以看到，此时批量 delete 和 insert 的语句被解析出来了，并且能够成功生成回滚的 SQL。

但是，DDL 语句，在整个测试过程中都是无法被回滚的，这也在我们的预期中，至此，MySQL 闪回工具 -- binlog2sql 的基本测试就告一段落了。

总结

利用 binlog2sql 来做闪回的前提如下：

1、在配置文件中设置了以下参数：

[mysqld]
server_id = 1
log_bin = /var/log/mysql/mysql-bin.log
max_binlog_size = 1G
binlog_format = row
binlog_row_image = full # 默认

2、在闪回的时候必须启动 MySQL 服务，因为它是通过 BINLOG_DUMP 协议来获取 binlog 内容，需要读取server端 information_schema.COLUMNS 表，来获取表结构的元信息，才能拼接成 SQL 语句。因此需要给用户提供的最小权限如下：

GRANT SELECT, REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'user'@'%';

看源码，主要是使用 python-mysql-replication 作为实时解析 MySQL binlog 来获取各个 EVENT。

python-mysql-replication 实现了 MySQL 复制协议，客户端伪装成 slave 来获取主的 binlog 和 EVENT。

具体可参考：

• https://github.com/noplay/python-mysql-replication
• http://python-mysql-replication.readthedocs.io/en/latest/_modules/pymysqlreplication/binlogstream.html

基于这一点，可以使用它通过读取 binlog 来实现一些完成实时计算，而无需先存储再计算。

但，这也是一个缺点，如果没有满足上面的前提，那么 binlog2sql 就无法完成工作。而且如果在高并发环境要进行解析 binlog，也就相当于多了一个同步线程在主上读取数据，加大了主的负担。

另外，有朋友在测试的时候，出现 SQL 解析不完整的情况，但是这个情况比较难遇到，已经和作者联系，表示有待验证。

所以，在生产上使用之前，务必先在测试环境测试通过之后再使用，确保没有数据错误。

从上面的测试也可以看出来，flashback 模式只支持 DML，DDL 不会输出；而且 flashback 模式下，一次性处理的 binlog 不宜过大，不能超过内存大小(有待优化)。

binlog2sql 官方文档：https://github.com/danfengcao/binlog2sql