mysqlbinlog工具做binlog server靠谱吗
玩过binlog server的同学都知道，它使用mysqlbinlog命令以daemon进程的方式模拟一个slave的IO线程与主库连接，可以很方便地即时同步主库的binlog，以便弥补定时备份策略中最近一次备份到下一次备份完成之前这段时间内的数据容易丢失的问题。
优点：备份出来的binlog不会受到主库expire_logs_days参数的影响，因为binlog server是模拟slave的IO线程，也不会受到从库relay_log_purge参数影响。这些binlog除非你手动清理，否则就会持续累计。so，你可以使用这些binlog+主库的全备做基于时间点和pos点的数据恢复。
缺点：因为binlog server是模拟slave的IO线程，所以在主库crash的时间点，具有与真正的slave相同的来不及同步主库最后一部分数据的风险。除此之外，binlog server本身也有bug。问题来了，这个bug是什么bug？为什么会有这个bug？这个bug在等到官方修复之前，有没有什么替代方案？请看下文分析过程
背景
数据库版本：5.7.18
数据库关键配置参数
双一，log_slave_updates，log-bin，slave_parallel_workers=16，binlog_rows_query_log_events=ON，server-id=3306250，slave_parallel_type=LOGICAL_CLOCK，slave_rows_search_algorithms='INDEX_SCAN,HASH_SCAN'，innodb_page_cleaners=4
数据库IP：主库IP 10.10.30.250，binlog server IP 10.10.30.217，下文中提到的服务器信息分别使用master和binlog server代替IP
服务器配置
CPU：16 vcpus
内存：64G
磁盘：100G flash卡
网卡：Speed: 100Mb/s
一 、建测试库表
创建数据库
localhost : (none) 03:07:20> CREATE DATABASE `xiaoboluo`;
创建表
localhost : (none) 03:07:20> CREATE TABLE `test` (
>`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
>`test` varchar(100) COLLATE utf8_bin DEFAULT NULL,
>`test2` varchar(100) COLLATE utf8_bin DEFAULT NULL,
>PRIMARY KEY (`id`)
) ENGINE=InnoDB;
二 、使用binlog server
本文演示binlog server需要使用到mysqlbinlog的相关选项如下
–defaults-file=file_name：仅读取该选项指定的配置文件
–host=host_name, -h host_name：在使用binlog server时，指定从哪台mysql server主机上获取二进制日志
–password[=password], -p[password]：连接到服务器时使用的密码
–port=port_num, -P port_num：用于连接到远程server的TCP / IP端口号
–raw：默认情况下，不使用–raw选项，mysqlbinlog读取二进制日志文件，并解析为文本格式输出事件(直接打印在标准输出中，可以使用输出重定向到文件中，也可以使用–result-file选项指定输出文件)， –raw选项告诉mysqlbinlog仍然以读取binlog时的原始二进制格式输出。该选项需要结合–read-from-remote-server选项使用
–read-from-remote-server, -R>
1、使用该选项时，mysqlbinlog会伪装成一个slave，连接读取，请求指定的binlog file，主库获取接收到这个请求之后就创建一个binlog dump线程推送binlog给mysqlbinlog server。
2、从MySQL server读取二进制日志，而不是读取本地日志文件。对于这些选项–host，–password，–port，–protocol，–socket和–user，除非给出了–read-from-remote-server选项结合使用，否则单独指定这些TCP/IP连接选项将被忽略不生效
–result-file=name, -r name：不与–raw选项一并使用时，此选项指定一个mysqlbinlog解析的文本存放的文件，当单独使用–raw选项时，mysqlbinlog会使用从远程server传输的原始binlog格式写入本地文件中，默认情况下输出文件与原始日志文件使用相同的文件名称。如果与–raw选项一并使用时，–result-file选项值会修改输出文件名的前缀，如：原本是mysql-bin.000001，使用–result-file=binlog，则输出文件名为binlogmysql-bin.000001
更多选项信息详见官方文档链接：https://dev.mysql.com/doc/refman/5.7/en/mysqlbinlog.html
2.1. binlog server原始格式转储
原始格式转储同步需要使用–raw选项，使用该选项时会以master实例中原始的binlog格式和文件名转储到binlog server本地系统指定目录下存放，下面是演示步骤
登录到master服务器的数据库实例中，执行刷新日志并查看日志文件编号到多少了
localhost : (none) 03:13:05> flush logs;
Query OK, 0 rows affected (0.01 sec)
localhost : (none) 03:18:23> show binary logs;
| mysql-bin.000032 | > 4721608 |
| mysql-bin.000033 | > > > 281 |
| mysql-bin.000034 | > > >3273 |
| mysql-bin.000035 | > > >1777 |
| mysql-bin.000036 | > > >1777 |
| mysql-bin.000037 | > > > 655 |
| mysql-bin.000038 | > > > 234 |
+------------------+-----------+
38 rows in set (0.00 sec)
从上面可以看到，最后一个binlog file是mysql-bin.000038，记录下这个文件名登录到binlog server服务器中，使用mysqlbinlog如下命令启动一个binlog server进程(带–raw选项)
# 先创建一个用于存放binlog server转储的文件目录，并进入到这个目录下启动mysqlbinlog进程，因为mysqlbinlog使用--raw选项时无法指定输出路径，只能转储到工作目录下，所以需要先使用cd命令切换路径
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba ~]# mkdir /data/backup/binlogserver/
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba ~]# cd /data/backup/binlogserver/
# 启动mysqlbinlog进程并挂后台执行
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# mysqlbinlog --host=10.10.30.250 --password=password --user=admin --read-from-remote-server mysql-bin.000038 --raw --stop-never &
# 查看工作目录，可以发现文件已经被同步过来了，此时主库还没有写入任何东西
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# ll
total 4
-rw-r----- 1 root root 123 May 22 16:08 mysql-bin.000038
现在登录到master的数据库实例中，写入几行测试数据，留意第二次insert语句的值改为了2017-05-23
localhost : (none) 03:51:47> insert into xiaoboluo.test(test) values('2017-05-22 00:03:26');
Query OK, 1 row affected (0.00 sec)
localhost : (none) 04:09:46> insert into xiaoboluo.test(test) values('2017-05-23 00:03:26');
Query OK, 1 row affected (0.00 sec)
localhost : (none) 04:09:50>
到binlog server中解析binlog mysql-bin.000038，查看转储的binlog内容
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# mysqlbinlog -vv >mysql-bin.000038
...... > #这里我们直接查看最后一个事务，即最后一个BEGIN开始往后的内容即可
BEGIN
/*!*/;
# at 746
#170522 16:09:50 server id 3306250 >end_log_pos 832 CRC32 0x434a1500 > >Rows_query
# insert into xiaoboluo.test(test) values('2017-05-23 00:03:26')
# at 832
#170522 16:09:50 server id 3306250 >end_log_pos 890 CRC32 0x8fbe85a5 > >Table_map: `xiaoboluo`.`test` mapped to number 249
# at 890
#170522 16:09:50 server id 3306250 >end_log_pos 951 CRC32 0x41154915 > >Write_rows: table id 249 flags: STMT_END_F
BINLOG '
zpwiWR0KczIAVgAAAEADAACAAD5pbnNlcnQgaW50byB4aWFvYm9sdW8udGVzdCh0ZXN0KSB2YWx1ZXMoJzIwMTctMDUtMjMgMDA6MDM6MjYnKQAVSkM=
zpwiWRMKczIAOgAAAHoDAAAAAPkAAAAAAAEACXhpYW9ib2x1bwAEdGVzdAADAw8PBCwBLAEGpYW+jw==
zpwiWR4KczIAPQAAALcDAAAAAPkAAAAAAAEAAgAD//z4wQIAEwAyMDE3LTA1LTIzIDAwOjAzOjI2FUkVQQ==
'/*!*/;
### INSERT INTO `xiaoboluo`.`test`
### SET
### > @1=180728 /* INT meta=0 nullable=0 is_null=0 */
### > @2='2017-05-23 00:03:26' /* VARSTRING(300) meta=300 nullable=1 is_null=0 */ >#这里可以看到在master中写入的第二行数据，日期为2017-05-23的那一行
### > @3=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
ROLLBACK /* added by mysqlbinlog */ /*!*/; >#留意这里，这里按照正常逻辑来讲，应该是一个带commit语句和xid号的 event，然而这里却是一个rollback语句
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*/;
从上面的结果中可以看到，master中第二个insert语句数据，binlog server通过mysqlbinlog命令转储之后，解析转储二进制日志文件的输出文本中并没有打commit语句，也就是说，使用mysqlbinlog转储的binlog进行数据恢复时，第二个insert语句的数据将被回滚掉，导致数据丢失
现在，登录到master中解析一下这个binlog文件中第二个insert数据是如何记录的呢
[root@e710d318-d5b4-4bc7-a606-d09f06ff5f5d binlog]# mysqlbinlog -vv >mysql-bin.000038
......
BEGIN
/*!*/;
# at 746
#170522 16:09:50 server id 3306250 >end_log_pos 832 CRC32 0x434a1500 > >Rows_query
# insert into xiaoboluo.test(test) values('2017-05-23 00:03:26')
# at 832
#170522 16:09:50 server id 3306250 >end_log_pos 890 CRC32 0x8fbe85a5 > >Table_map: `xiaoboluo`.`test` mapped to number 249
# at 890
#170522 16:09:50 server id 3306250 >end_log_pos 951 CRC32 0x41154915 > >Write_rows: table id 249 flags: STMT_END_F
BINLOG '
zpwiWR0KczIAVgAAAEADAACAAD5pbnNlcnQgaW50byB4aWFvYm9sdW8udGVzdCh0ZXN0KSB2YWx1ZXMoJzIwMTctMDUtMjMgMDA6MDM6MjYnKQAVSkM=
zpwiWRMKczIAOgAAAHoDAAAAAPkAAAAAAAEACXhpYW9ib2x1bwAEdGVzdAADAw8PBCwBLAEGpYW+jw==
zpwiWR4KczIAPQAAALcDAAAAAPkAAAAAAAEAAgAD//z4wQIAEwAyMDE3LTA1LTIzIDAwOjAzOjI2FUkVQQ==
'/*!*/;
### INSERT INTO `xiaoboluo`.`test`
### SET
### > @1=180728 /* INT meta=0 nullable=0 is_null=0 */
### > @2='2017-05-23 00:03:26' /* VARSTRING(300) meta=300 nullable=1 is_null=0 */ >#日期为2017-05-23的数据在这里
### > @3=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
# at 951
#170522 16:09:50 server id 3306250 >end_log_pos 982 CRC32 0x60d092ff > >Xid = 1156777
COMMIT/*!*/; ># 可以看到master中记录的binlog是正常的，代表这个事务在主库已经正常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*/;
通过以上解析结果对比可以看到，mysqlbinlog同步机制使用原始格式转储的binlog文件中，最后一个事务原本应该是commit的语句，然而却是rollback，为什么会这样呢？稍安勿躁，稍后见第3节总结部分，这里咱们先看看binlog server文本格式转储是不是也有这个问题呢？
2.2.binlog server文本格式转储
不使用–raw选项时，mysqlbinlog读取master实例的binlog之后，在转储之前会解析为文本格式的事件日志输出，可以使用输出重定向到一个文件中保存，也可以使用–result-file=file选项指定一个文件进行存放，解析结果只能转储到同一个文件中，主库有新的binlog产生时，会在该文件末尾持续追加，下面是演示步骤
登录到binlog server服务器中，停止mysqlbinlog进程并清空/data/backup/binlogserver目录
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# killall mysqlbinlog
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# ps aux |grep mysqlbinlog
root > > 11878 >0.0 >0.0 103252 > 840 pts/0 > >S+ > 16:34 > 0:00 grep mysqlbinlog
[1]+ >Terminated > > > > > > >mysqlbinlog --host=10.10.30.250 --password=password --user=admin --read-from-remote-server mysql-bin.000038 --raw --stop-never
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# rm -rf *
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# ll
total 0
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]#
登录到master服务器的数据库实例中，执行刷新日志并查看日志文件编号到多少了
localhost : (none) 04:09:50> flush logs;
Query OK, 0 rows affected (0.01 sec)
localhost : (none) 04:35:04> show binary logs;
| mysql-bin.000034 | > > >3273 |
| mysql-bin.000035 | > > >1777 |
| mysql-bin.000036 | > > >1777 |
| mysql-bin.000037 | > > > 655 |
| mysql-bin.000038 | > > >1029 |
| mysql-bin.000039 | > > > 234 |
+------------------+-----------+
39 rows in set (0.00 sec)
从上面可以看到，最后一个binlog file是mysql-bin.000039，记录下这个文件名登录到binlog server服务器中，使用mysqlbinlog如下命令启动一个binlog server进程(不带–raw选项，添加–result-file=binlog_parse)
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba ~]# cd /data/backup/binlogserver/
# 启动mysqlbinlog并挂后台执行（注意：为了演示需要，把base-64编码解析为可读格式的sql语句，加上了-vv选项，实际生产环境如果要用于重放，请不要添加-vv选项）
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# mysqlbinlog --host=10.10.30.250 --password=password --user=admin --read-from-remote-server mysql-bin.000039 \
--result-file=binlog_parse --stop-never -vv &
# 查看工作目录，可以发现目录下多了一个binlog_parse文件，此时主库还没有写入任何东西
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# ll
total 4
-rw-r----- 1 root root 741 May 22 16:38 binlog_parse
现在登录到master的数据库实例中，写入几行测试数据，留意这里第二个insert的值改为了2017-05-23
localhost : (none) 04:35:11> insert into xiaoboluo.test(test) values('2017-05-22 00:03:26');
Query OK, 1 row affected (0.01 sec)
localhost : (none) 04:39:15> insert into xiaoboluo.test(test) values('2017-05-23 00:03:26');
Query OK, 1 row affected (0.00 sec)
localhost : (none) 04:39:18>
到binlog server中查看已经被mysqlbinlog命令解析并转储的binlog文本文件binlog_parse
[root@4ee3a2ca-0be4-4057-a415-0ac5c05363ba binlogserver]# cat binlog_parse
...... > #这里我们直接查看最后一个事务，即最后一个BEGIN开始往后的内容即可
BEGIN
/*!*/;
# at 746
#170522 16:39:18 server id 3306250 >end_log_pos 832 CRC32 0xe3c8e631 > >Rows_query
# insert into xiaoboluo.test(test) values('2017-05-23 00:03:26')
# at 832
#170522 16:39:18 server id 3306250 >end_log_pos 890 CRC32 0x7debb044 > >Table_map: `xiaoboluo`.`test` mapped to number 249
# at 890
#170522 16:39:18 server id 3306250 >end_log_pos 951 CRC32 0xabb8de46 > >Write_rows: table id 249 flags: STMT_END_F
BINLOG '
tqMiWR0KczIAVgAAAEADAACAAD5pbnNlcnQgaW50byB4aWFvYm9sdW8udGVzdCh0ZXN0KSB2YWx1ZXMoJzIwMTctMDUtMjMgMDA6MDM6MjYnKTHmyOM=
tqMiWRMKczIAOgAAAHoDAAAAAPkAAAAAAAEACXhpYW9ib2x1bwAEdGVzdAADAw8PBCwBLAEGRLDrfQ==
tqMiWR4KczIAPQAAALcDAAAAAPkAAAAAAAEAAgAD//z8wQIAEwAyMDE3LTA1LTIzIDAwOjAzOjI2Rt64qw==
'/*!*/;
### INSERT INTO `xiaoboluo`.`test`
### SET
### > @1=180732 /* INT meta=0 nullable=0 is_null=0 */
### > @2='2017-05-23 00:03:26' /* VARSTRING(300) meta=300 nullable=1 is_null=0 */ >#日期为2017-05-23的event在这里
### > @3=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
# at 951
#170522 16:39:18 server id 3306250 >end_log_pos 982 CRC32 0x29f585cc > >Xid = 1156784
COMMIT/*!*/; >#这里可以看到commit语句在不带--raw时被正确转储了
从上面的结果中可以看到，master中第二个insert语句插入的数据的commit标记被正确转储了，也就是说，binlog server通过mysqlbinlog命令转储的二进制日志在不使用–raw选项时（使用文本格式转储时），不会导致数据丢失
现在，登录到master中解析一下这个binlog文件中第二个Insert语句的数据，做个对比
[root@e710d318-d5b4-4bc7-a606-d09f06ff5f5d binlog]# mysqlbinlog -vv >mysql-bin.000038
......
BEGIN
/*!*/;
# at 746
#170522 16:39:18 server id 3306250 >end_log_pos 832 CRC32 0xe3c8e631 > >Rows_query
# insert into xiaoboluo.test(test) values('2017-05-23 00:03:26')
# at 832
#170522 16:39:18 server id 3306250 >end_log_pos 890 CRC32 0x7debb044 > >Table_map: `xiaoboluo`.`test` mapped to number 249
# at 890
#170522 16:39:18 server id 3306250 >end_log_pos 951 CRC32 0xabb8de46 > >Write_rows: table id 249 flags: STMT_END_F
BINLOG '
tqMiWR0KczIAVgAAAEADAACAAD5pbnNlcnQgaW50byB4aWFvYm9sdW8udGVzdCh0ZXN0KSB2YWx1ZXMoJzIwMTctMDUtMjMgMDA6MDM6MjYnKTHmyOM=
tqMiWRMKczIAOgAAAHoDAAAAAPkAAAAAAAEACXhpYW9ib2x1bwAEdGVzdAADAw8PBCwBLAEGRLDrfQ==
tqMiWR4KczIAPQAAALcDAAAAAPkAAAAAAAEAAgAD//z8wQIAEwAyMDE3LTA1LTIzIDAwOjAzOjI2Rt64qw==
'/*!*/;
### INSERT INTO `xiaoboluo`.`test`
### SET
### > @1=180732 /* INT meta=0 nullable=0 is_null=0 */
### > @2='2017-05-23 00:03:26' /* VARSTRING(300) meta=300 nullable=1 is_null=0 */
### > @3=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
# at 951
#170522 16:39:18 server id 3306250 >end_log_pos 982 CRC32 0x29f585cc > >Xid = 1156784
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*/;
从上面的结果中可以看到，文本格式转储并不会导致最后一个事务的commit被替换为rollback，你可以使用文本格式转储主库binlog，虽然避免了数据丢失，但是问题也显而易见…就是需要进行恢复时，因为是已经解析过的文本，所以不能使用–start-，–stop-这些选项来过滤查找你想要的数据，需要手工来完成这个工作。数据量小还好，数据量大了就…不管怎样，也勉强算是解决了原始格式转储的问题。至于你要不要用，那就见仁见智了。
三、总结
从2.1和2.2小节的对比演示可以看到
mysqlbinlog使用–raw选项以binlog日志原始格式转储时，通过解析转储文件发现来自master的最后一个事务的commmit标记缺失了，会导致利用mysqlbinlog转储的binlog文件做数据恢复时，丢失最后一个事务，因为这最后一个事务原本是commit标记的位置使用的是rollback语句，会导致这最后一个事务被回滚掉，为什么这个commit语句缺失了以及为什么多了一个rollback语句？因为在mysqlbinlog工具的源码中，转储binlog文件到磁盘是调用glibc来写文件，当mysqlbinlog伪装的slave在连接master使用–raw+–read-from-remote-server 选项时，glibc的缓存会把最后一个event留在内存中不调用fflush函数落盘(但master的binlog dump线程把mysqlbinlog的连接仍然当作一个正常的slave一样把完整的binlog发送过去给mysqlbinlog了)，所以当你启动另外一个mysqlbinlog进程去解析这个binlog文件时，并没有看到最后一个事务的commit标记，但是却看到了rollback(这个rollback语句只要调用mysqlbinlog命令结束都会加上的，要注意，这个rollback语句是你用于解析这个binlog文件的那一个mysqlbinlog进程加上的，跟binlog server的那一个mysqlbinlog没关系，binlog server的那一个mysqlbinlog进程还仍然再运行中，还卡在最后一个commit未落盘这里)
mysqlbinlog不使用–raw选项时，mysqlbinlog同步的binlog被直接解析为文本格式转储，这个时候转储的binlog内容中最后一个事务与主库中记录的一致，都带有commit语句，即这个时候使用mysqlbinlog转储的binlog做数据恢复时，不会发生数据丢失，那这个时候为什么有commit语句而没有rollback语句呢？因为非raw模式的转储时（即只使用–read-from-remote-server 选项不使用–raw选项），mysqlbinlog解析时会调用glibc的fflush函数强制把缓存中的数据刷新到文件中，所以不使用–raw选项时就会有commit语句，而缺失这个rollback语句是因为转储binlog的mysqlbinlog进程仍然在继续运行，只有在mysqlbinlog结束的时候才会加上rollback语句。那为什么使用–raw模式的时候mysqlbinlog也在运行，解析出来的binlog文件就有rollback语句呢？还记得是另外调用了一个mysqlbinlog命令来解析的吗？解析binlog的这个mysqlbinlog进程在执行完解析之后就退出了，so…
因为binlog server在持续运行期间，最后一个事务的commit标记总是不落盘（除非你正常停止这个binlog server进程），所以，如果经济上允许，建议单独使用一台服务器，搭建一个备份专用备库，还可以避免备份与线上业务访问相互影响的问题，系统参数relay_log_purge别忘记设置为OFF，因为是备份binlog专用的备库，所以表引擎可以改为blackhole引擎。
注意：
mysqlbinlog server在加了–stop-never选项之后就会一直监听所连接的server是否有新的events发送过来，也正因为如此，导致了最后一个事务的commit语句一直不能落盘，直到主库有新的events发送过来时，这个事务的commit才会被触发写盘。如果不使用–stop-never选项当然就没有问题，因为mysqlbinlog在读取了server最后一个binlog文件之后会退出，退出时会把缓存中的events都落盘。但是这也会导致了无法即时转储主库的数据更新。
在MySQL 5.7.x版本中，mysqlbinlog工具解析任何一个本地的binlog或relay log时，都不会在mysqlbinlog命令执行结束时追加rollback语句，但在MySQL 5.6.x版本中，mysqlbinlog工具解析每一个本地binlog和relay log时在mysqlbinlog命令退出时都会加rollback语句