MySQL binlog server原理与搭建

1 | 背景

MySQL包含许多种日志，其中包括：redo log、undo log、error log、binlog等等，其中binlog是区别其他关系型数据库所独有的，也是MySQL中最重要的日志之一，其作用是用于主备复制、闪回、基于时间点恢复等等；本文基于公司产品需求，对比研究5.7版本下binlog server备份binlog的功能，以及该工具的优缺点。

2 | 测试环境

操作系统：CentOS 7.4
MySQL版本：5.7.27/5.7.18
数据库关键配置参数：log-bin=1；binlog_format=ROW；binlog_row_image=FULL
MySQL server：10.10.30.243（qfusion1）
binlog server：10.10.30.246（qfusion3）

3 | binlog server原理

3.1 请求方式

显式指定一组binlog文件：对于每个文件，mysqlbinlog连接并发出binlog dump命令。server发送文件完成后断开连接（因为mysqlbinlog指定server ID为0）。每个文件有一个连接（one connection per file）。
指定开始binlog文件和--to-last-log：mysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件完成后断开连接（因为mysqlbinlog指定server id为0）。
指定开始binlog文件和--stop-never：mysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件，但在发送最后一个文件后不会断开连接（mysqlbinlog指定了非零server ID）。

注意：

MySQL从库如果省略server-id（默认值0）或设置为0，则slave拒绝连接到master（ERROR] Server id not set, will not start slave for channel ''）

3.2 工作形态

未开启binlog server进程的MySQL主库

root@localhost : (none) 03:17:44> show processlist;
+----+------+-----------+------+---------+------+----------+------------------+
| Id | User | Host      | db   | Command | Time | State    | Info             |
+----+------+-----------+------+---------+------+----------+------------------+
| 20 | root | localhost | NULL | Query   |    0 | starting | show processlist |
+----+------+-----------+------+---------+------+----------+------------------+
1 row in set (0.00 sec)

binlog server节点开启备份进程

[root@qfusion3 backup]# mysqlbinlog -R --raw -upowdba -h10.10.30.243 -pxxx --stop-never mysql-bin.000001 --result-file=/data/backup/ &
[1] 4323

开启binlog server进程MySQL主库

root@localhost : (none) 03:17:45> show processlist;
+----+------+--------------------+------+-------------+------+---------------------------------------------------------------+------------------+
| Id | User | Host               | db   | Command     | Time | State                                                         
| Info             |
+----+------+--------------------+------+-------------+------+---------------------------------------------------------------+------------------+
| 20 | root | localhost          | NULL | Query       |    0 | starting                                                      
| show processlist |
| 21 | root | 10.10.30.150:39154 | NULL | Binlog Dump |    3 | Master has sent all binlog to slave; waiting for more updates | NULL             |
+----+------+--------------------+------+-------------+------+---------------------------------------------------------------+------------------+
2 rows in set (0.00 sec)

可以看到binlog server的工作方式是模拟MySQL的主从，主库上会有Binlog Dump线程用于推送binlog到binlog server节点，binlog server节点类似于io thread接收binlog，并存放在本地。

4 | binlog server重要参数

--raw：

默认情况下不使用--raw选项，mysqlbinlog读取的binlog文件解析为文本格式输出（直接打印在标准输出中，可以使用输出重定向到文件中，也可以使用--result-file选项指定输出文件）。
使用--raw选项时，mysqlbinlog仍然以读取binlog时的原始二进制格式输出。该选项需要结合--read-from-remote-server选项使用，因为mysqlbinlog使用--raw选项输出原始格式的文件来源是从远程server中读取的，因为mysqlbinlog server一直和主库保持连接（使用--stop-never选项之后，在读取主库最后一个binlog之后仍然保持着与主库的连接不断开）。默认情况下，binlog server的输出文件名称与读取的原始日志文件相同，而且会存放在当前路径下，但输出文件名前缀可以使用--result-file选项修改。
注意：

1、如果中途读取发生错误，mysqlbinlog进程会被终止。2、如果中途读取异常终止，重新启动mysqlbinlog进程会重新获取binlog信息（直接覆盖文件）；不会自动检测是否文件中已经存在event。3、指定的binlog起始文件mysql-bin.000001会使用这个文件名到master的binlog目录下的mysql-bin.index文件中查找，如果没有找到就报错终止，找到了就依次往后读取index文件中的binlog。--read-from-remote-server, -R：

远程读取其他mysql server的binlog日志，而不是读取本地日志文件。对于选项--host，--password，--port，--protocol，--socket和--user，除非给出了--read-from-remote-server选项结合使用，否则单独指定这些TCP/IP连接选项将被忽略不生效。
使用该选项时，mysqlbinlog会伪装成一个slave，类似于主从复制时io thread读取master的binlog。主库获取接收到这个请求之后就创建一个binlog dump线程推送binlog给binlog server节点。
注意：

仅使用--read-from-remote-server时，mysqlbinlog使用server id为0连接，该server id告知mysqlbinlog进程在接收最后请求的日志文件后断开连接。联合使用--read-from-remote-server和--stop-never时，mysqlbinlog使用非零server id连接，因此mysqlbinlog进程在接收最后一个日志文件后不会断开连接。默认情况下， server id为65535，但可以使用--stop-never-slave-server-id参数更改。--result-file=name, -r name：

此选项指定mysqlbinlog解析的文本存放的位置。
当使用--raw选项，不使用--result-file时，mysqlbinlog会使用从远程mysql server传输的原始binlog格式写入本地文件中，默认情况下输出文件与原始日志文件使用相同的文件名称。
如果与--raw选项一并使用时，--result-file选项值会修改输出文件名的前缀，如：原本是mysql-bin.000001，使用--result-file=binlog，则输出文件名为binlogmysql-bin.000001

--stop-never：

此选项需要与--read-from-remote-server一起使用时才有效，它告诉mysqlbinlog保持与server的连接。如果不使用该选项，传输完成server中最后一个日志文件时，mysqlbinlog命令将退出，使用--stop-never选项时传输完成server的最后一个日志文件仍然保持与server的连接。
--stop-never通常与--raw选项一起使用，进行实时的二进制格式的日志备份，当不与--raw选项一起使用时，远程传输的binlog文件不会以二进制格式写入本地，而是直接解析为日志事件输出。

--stop-never-slave-server-id=id

默认65535。使用此选项需要REPLICATION SLAVE权限

如果同一个master有多个remote binlog server，需要给binlog server指定 server-id，那么使用参数--stop-never-slave-server-id显式指定连接master的server id值，可以用于避免与其他slave的server id冲突。

--to-last-log：

不要在MySQL服务器的请求binlog日志结束时停止，而是继续打印直到最后一个binlog日志结束。如果将输出发送到同一MySQL服务器，这可能会导致无限循环。此选项需要--read-from-remote-server一起使用。

注意：

使用--stop-never时，没有必要指定--to-last-log来读取最后一个日志文件，因为该选项是隐藏的。

5 | binlog server验证（MySQL5.7.27）

5.1. binlog server使用--raw选项

使用--raw选项时，会以mysqlbinlog连接实例中原始的binlog格式和文件名在执行mysqlbinlog命令的本地系统目录下存放。①、登录MySQL server所在主机，创建表结构，查看binlog的编号信息

root@localhost : test 02:23:36> create table test (
    -> id int primary key,
    -> name varchar(10)
    -> );
Query OK, 0 rows affected (0.03 sec)

root@localhost : test 02:23:53> flush binary logs;
Query OK, 0 rows affected (0.02 sec)

root@localhost : test 02:24:05> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       398 |
| mysql-bin.000002 |       194 |
+------------------+-----------+
2 rows in set (0.00 sec)

②、登录binlog server节点，开启备份binlog进程和strace追踪进程

[root@qfusion3 ~]# cd /data/backup/

[root@qfusion3 backup]# ls

[root@qfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file=/data/backup/ &

[root@qfusion3 backup]# ls
mysql-bin.000001  mysql-bin.000002

[root@qfusion3 ~]# strace -T -tt -p `pidof mysqlbinlog` -o /root/strace_0.log

③、到MySQL server所在主机，登录MySQL，并插入数据

oot@localhost : test 02:24:10> insert into test values(1,'1');
Query OK, 1 row affected (0.01 sec) 

root@localhost : test 02:26:20> insert into test values(2,'2');
Query OK, 1 row affected (0.00 sec)

④、到binlog server所在节点，查看binlog信息和strace情况

查看strace追踪mysqlbinlog进程情况

[root@qfusion3 ~]# cat strace_0.log
... ###查看最后一个事务相关信息
21:34:03.833476 recvfrom(3, 
"B20K31P]!32!%A=2303312v2022423021"..., 16384, 0, NULL, NULL) = 344 <5.144848> ###344代表接收该事务的总字节大小
21:34:08.978398 lseek(4, 0, SEEK_CUR)   = 508 <0.000021> ###508代表当前位置的偏移字节（查看下面binlog的该事务开始的pos位点）
21:34:08.978470 write(4, "K31P]!32!%A=2303312v2022423021351237302372342"..., 65) = 65 <0.000032> ###65代表接收Gtid event大小（查看下面binlog的pos和end_log_pos位点信息：573-508=65）
21:34:08.978548 lseek(4, 0, SEEK_CUR)   = 573 <0.000025>###573代表当前位置的偏移字节（查看下面binlog的Gtid event开始的pos位点）
21:34:08.978606 write(4, "K31P]232!%H205210]+432"..., 72) = 72 <0.000015> ###72代表接收Query event大小（查看下面binlog的pos和end_log_pos位点信息：645-573=72）
21:34:08.978649 lseek(4, 0, SEEK_CUR)   = 645 <0.000010>###645代表当前位置的偏移字节（查看下面binlog的Query event开始的pos位点）
21:34:08.978675 write(4, "K31P]3532!%006273220036insert into "..., 54) = 54 <0.000012> ###54代表接收Rows_query event大小（查看下面binlog的pos和end_log_pos位点信息：699-645=54）
21:34:08.978731 lseek(4, 0, SEEK_CUR)   = 699 <0.000013>###699代表当前位置的偏移字节（查看下面binlog的Rows_query event开始的pos位点）
21:34:08.978778 write(4, "K31P]2332!%0023552.314test"..., 50) = 50 <0.000012> ###50代表接收Table_map event大小（查看下面binlog的pos和end_log_pos位点信息：749-699=50）
21:34:08.978824 lseek(4, 0, SEEK_CUR)   = 749 <0.000008>###749代表当前位置的偏移字节（查看下面binlog的Table_map event开始的pos位点）
21:34:08.978852 write(4, "K31P]3632!%*273.3122377374"..., 42) = 42 <0.000008> ###42代表接收Write_rows event大小（查看下面binlog的pos和end_log_pos位点信息：791-749=42）
21:34:08.978888 lseek(4, 0, SEEK_CUR)   = 791 <0.000008>###791代表当前位置的偏移字节（查看下面binlog的Write_rows event开始的pos位点）
21:34:08.978915 write(4, "K31P]2032!%370063252353;301Lm5", 31) = 31 <0.000020> ###31代表接收Xid event大小（查看下面binlog的pos和end_log_pos位点信息：822-791=31）

通过strace追踪信息可以看出，binlog server在接收到主库mysqld的binlog的event后会立即调用write()写入到磁盘。查看备份binlog内容

[root@qfusion3 backup]# mysqlbinlog -vv --base64-output=DECODE-ROWS mysql-bin.000002
... ###直接查看最后一个事务event
# at 508
#190811 21:34:03 server id 2433306  end_log_pos 573 CRC32 0x657ee1b7     GTID    last_committed=1    sequence_number=2    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'c3ca7682-a218-11e9-9fc2-fae2559a6c00:3'/*!*/;
# at 573
#190811 21:34:03 server id 2433306  end_log_pos 645 CRC32 0x7c9f876f     Query    thread_id=11101    exec_time=0    error_code=0
SET TIMESTAMP=1565530443/*!*/;
BEGIN
/*!*/;
# at 645
#190811 21:34:03 server id 2433306  end_log_pos 699 CRC32 0x35eea843     Rows_query
# insert into test values(2,'2')
# at 699
#190811 21:34:03 server id 2433306  end_log_pos 749 CRC32 0x5244ee3b     Table_map: 
`test`.`test` mapped to number 814
# at 749
#190811 21:34:03 server id 2433306  end_log_pos 791 CRC32 0xa9c03605     Write_rows: table id 814 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='2' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
# at 791
#190811 21:34:03 server id 2433306  end_log_pos 822 CRC32 0x356d4cc1     Xid = 3926954
COMMIT/*!*/; ###这里可以看到，最后一个事务的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解析结果对比可以看到，MySQL 5.7.27版本下使用--raw选项的binlog server备份的binlog时，主库mysqld的所有提交事务的binlog是被完全备份（最后一个事务的commit语句被实时备份）。

5.2 binlog server不使用--raw选项

①、登录MySQL server所在主机，创建表结构，查看binlog的编号信息

root@localhost : test 02:36:47> create table test (
    -> id int primary key,
    -> name varchar(10)
    -> );
Query OK, 0 rows affected (0.03 sec)

root@localhost : test 02:37:02> flush binary logs;
Query OK, 0 rows affected (0.02 sec)

root@localhost : test 02:37:09> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       398 |
| mysql-bin.000002 |       194 |
+------------------+-----------+
2 rows in set (0.00 sec)

②、登录binlog server主机，开启备份binlog进程和strace追踪进程

[root@qfusion3 ~]# cd /data/backup/

[root@qfusion3 backup]# ls

###这里对mysqlbinlog加上-vv选项便于后面观看，生产环境慎用
[root@qfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file=/data/backup/backup_binlog -vv &

[root@qfusion3 backup]# ls
backup_binlog

[root@qfusion3 ~]# strace -T -tt -p `pidof mysqlbinlog` -o /root/strace_1.log

③、到MySQL server所在主机，登录MySQL，并插入数据

root@localhost : test 02:37:11> insert into test values(1,'1');
Query OK, 1 row affected (0.01 sec)

root@localhost : test 02:38:13> insert into test values(2,'2');
Query OK, 1 row affected (0.01 sec)

④、到binlog server所在节点，查看binlog信息和strace情况

查看strace追踪mysqlbinlog进程情况

[root@qfusion3 ~]# cat strace_1.log
... ###查看最后一个事务相关信息
22:52:15.944162 write(3, "# at 477
#190811 22:52:10 server"..., 106) = 106 <0.000005>
22:52:15.944181 recvfrom(4, 
"B20240+P]!32!%A=2303312v2022423021"..., 16384, 0, NULL, 
NULL) = 344 <6.262410>
22:52:22.206755 lseek(3, 0, SEEK_CUR)   = 3650 <0.000009>
22:52:22.206835 write(3, "# at 508
#190811 22:52:16 server"..., 268) = 268 <0.000027>
22:52:22.206912 lseek(3, 0, SEEK_CUR)   = 3918 <0.000005>
22:52:22.206938 write(3, "# at 573
#190811 22:52:16 server"..., 170) = 170 <0.000005>
22:52:22.206979 lseek(3, 0, SEEK_CUR)   = 4088 <0.000038>
22:52:22.207067 write(3, "# at 645
#190811 22:52:16 server"..., 123) = 123 <0.000020>
22:52:22.207141 lseek(3, 0, SEEK_CUR)   = 4211 <0.000033>
22:52:22.207223 write(3, "# at 699
#190811 22:52:16 server"..., 125) = 125 <0.000007>
22:52:22.207280 lseek(3, 0, SEEK_CUR)   = 4336 <0.000021>
22:52:22.207353 write(3, "# at 749
#190811 22:52:16 server"..., 122) = 122 <0.000020>
22:52:22.207413 lseek(3, 0, SEEK_CUR)   = 4458 <0.000011>
22:52:22.207514 write(3, "
BINLOG '
oCtQXR0aISUANgAAALsCAA"..., 217) = 217 <0.000009>
22:52:22.207571 lseek(3, 0, SEEK_CUR)   = 4675 <0.000006>
22:52:22.207617 write(3, "### INSERT INTO `test`.`test`
##"..., 149) = 149 <0.000007>
22:52:22.207663 lseek(3, 0, SEEK_CUR)   = 4824 <0.000022>
22:52:22.207723 write(3, "# at 791
#190811 22:52:16 server"..., 106) = 106 <0.000020>

通过strace追踪信息可以看出，binlog server在接收到主库mysqld的binlog的event后会立即调用write()写入到磁盘

查看备份binlog内容

[root@qfusion3 backup]# cat backup_binlog
... ###直接查看最后一个事务event
# at 508
#190811 22:52:16 server id 2433306  end_log_pos 573 CRC32 0x4042ce43     GTID    last_committed=1    sequence_number=2    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'c3ca7682-a218-11e9-9fc2-fae2559a6c00:3'/*!*/;
# at 573
#190811 22:52:16 server id 2433306  end_log_pos 645 CRC32 0xe96924cd     Query    thread_id=11101    exec_time=0    error_code=0
SET TIMESTAMP=1565535136/*!*/;
BEGIN
/*!*/;
# at 645
#190811 22:52:16 server id 2433306  end_log_pos 699 CRC32 0x61ed5dd9     Rows_query
# insert into test values(2,'2')
# at 699
#190811 22:52:16 server id 2433306  end_log_pos 749 CRC32 0xa2d0e2c2     Table_map: `test`.`test` mapped to number 815
# at 749
#190811 22:52:16 server id 2433306  end_log_pos 791 CRC32 0x5ef22e57     Write_rows: table id 815 flags: STMT_END_F

BINLOG '
oCtQXR0aISUANgAAALsCAACAAB5pbnNlcnQgaW50byB0ZXN0IHZhbHVlcygyLCcyJynZXe1h
oCtQXRMaISUAMgAAAO0CAAAAAC8DAAAAAAEABHRlc3QABHRlc3QAAgMPAh4AAsLi0KI=
oCtQXR4aISUAKgAAABcDAAAAAC8DAAAAAAEAAgAC//wCAAAAATJXLvJe
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='2' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
# at 791
#190811 22:52:16 server id 2433306  end_log_pos 822 CRC32 0x39e136ce     Xid = 3979199
COMMIT/*!*/; ###这里可以看到最后一行数据的commit状态也被备份过来

通过以上解析结果对比可以看到，MySQL 5.7.27版本下不使用--raw选项的binlog server备份的binlog时，主库mysqld的所有提交事务的binlog是被完全备份（最后一个事务的commit语句被实时备份）。

6 | binlog server验证（MySQL5.7.18）

6.1. binlog server使用--raw选项

使用--raw选项时，会以mysqlbinlog连接实例中原始的binlog格式和文件名在执行mysqlbinlog命令的本地系统目录下存放。

①、登录MySQL server所在主机，创建表结构，查看binlog的编号信息

mysql> create table test (
    -> id int primary key,
    -> name varchar(10)
    -> );
Query OK, 0 rows affected (0.03 sec)

mysql> flush binary logs;
Query OK, 0 rows affected (0.02 sec)

mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       398 |
| mysql-bin.000002 |       194 |
+------------------+-----------+
2 rows in set (0.00 sec)

②、登录binlog server主机，开启备份binlog进程和strace追踪进程

[root@qfusion3 data]# cd backup/

[root@qfusion3 backup]# ls

[root@qfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file=/data/backup/ &

[root@qfusion3 backup]# ls
mysql-bin.000001  mysql-bin.000002

[root@qfusion3 backup]# strace -T -tt -p `pidof mysqlbinlog` -o /root/strace_2.log

③、到MySQL server所在主机，登录MySQL，并插入数据

mysql> insert into test values(1,'1');
Query OK, 1 row affected (0.01 sec)

mysql> insert into test values(2,'2');
Query OK, 1 row affected (0.01 sec)

[root@qfusion1 archive]# ll
total 12
-rw-r-----. 1 mysql mysql 557 Apr 22 10:22 mysql-bin.000001
-rw-r-----. 1 mysql mysql 822 Apr 22 10:22 mysql-bin.000002
-rw-r-----. 1 mysql mysql  80 Apr 22 10:22 mysql-bin.index

④、到binlog server节点，查看binlog信息和strace情况

查看strace追踪mysqlbinlog进程情况

[root@qfusion3 ~]# cat /root/strace_2.log
strace: Process 9886 attached
09:39:50.117381 recvfrom(3, 
"B
201303P]!352253$A311E+Q27327217721"..., 16384, 0, NULL, NULL) = 344 <25.821514>
09:40:15.939151 lseek(4, 0, SEEK_CUR) = 0 <0.000065>
09:40:15.939922 lseek(4, 0, SEEK_CUR) = 0 <0.000018>
09:40:15.939964 lseek(4, 0, SEEK_CUR) = 0 <0.000009>
09:40:15.939991 lseek(4, 0, SEEK_CUR) = 0 <0.000009>
09:40:15.940015 lseek(4, 0, SEEK_CUR) = 0 <0.000009>
09:40:15.940047 lseek(4, 0, SEEK_CUR) = 0 <0.000042>
09:40:15.940121 recvfrom(3,
"B20210303P]!352253$A=21E+Q27327217721"..., 16384, 0, NULL, NULL) = 344 <6.998697>
09:40:22.938964 lseek(4, 0, SEEK_CUR) = 0 <0.000022>
09:40:22.939050 lseek(4, 0, SEEK_CUR) = 0 <0.000030>
09:40:22.939117 lseek(4, 0, SEEK_CUR) = 0 <0.000009>
09:40:22.939143 lseek(4, 0, SEEK_CUR) = 0 <0.000008>
09:40:22.939165 lseek(4, 0, SEEK_CUR) = 0 <0.000008>
09:40:22.939188 lseek(4, 0, SEEK_CUR) = 0 <0.000008>

通过strace追踪信息可以看出，binlog server在接收到主库mysqld的binlog的event后没有调用write()写入到磁盘

查看备份binlog内容

[root@qfusion3 backup]# ll
total 4
rw-r-----. 1 root root 398 8月 12 09:39 mysql-bin.000001
-rw-r-----. 1 root root 0 8月 12 09:39 mysql-bin.000002

这里可以看到，binlog server备份的最后一个binlog文件（mysql-bin.000002）为空

⑤、到MySQL server再多执行insert，观察binlog server节点的binlog状态以及strace追踪情况

mysql> insert into test values(3,'3');
Query OK, 1 row affected (0.01 sec)
...
mysql> insert into test values(13,'13');
Query OK, 1 row affected (0.01 sec)

binlog server节点查看strace追踪mysqlbinlog进程情况

[root@qfusion3 backup]# cat /root/strace_2.log
...
09:48:50.925273 lseek(4, 0, SEEK_CUR) = 0 <0.000004>
09:48:50.925297 lseek(4, 0, SEEK_CUR) = 0 <0.000004>
09:48:50.925313 recvfrom(3, "BR211305P]!352253$A304171E+Q27327217721"..., 16384, 0, NULL, NULL) = 347 <5.837968>
09:48:56.763446 lseek(4, 0, SEEK_CUR) = 0 <0.000020>
09:48:56.763539 lseek(4, 0, SEEK_CUR) = 0 <0.000018>
09:48:56.763584 write(4, "376bin354302P]17352253$w{4005.7.18-"..., 4096) = 4096 <0.000033> ###字节数达到4096后调用一次write()
09:48:56.763663 lseek(4, 0, SEEK_CUR) = 4096 <0.000006>
09:48:56.763689 lseek(4, 0, SEEK_CUR) = 4096 <0.000004>
09:48:56.763711 lseek(4, 0, SEEK_CUR) = 4096 <0.000004>
09:48:56.763729 lseek(4, 0, SEEK_CUR) = 4096 <0.000003>

通过以上解析结果可以发现，binlog server备份binlog过程中，主库dump线程是发送event到binlog server节点（strace中lseek），但是没有落盘，直到接收字节大小超过4096后，才会调用write()写入到磁盘

binlog server节点查看binlog文件状态和binlog内容

[root@qfusion3 backup]# ll
总用量 8
-rw-r-----. 1 root root 398 8月 12 09:39 mysql-bin.000001
-rw-r-----. 1 root root 4096 8月 12 09:48 mysql-bin.000002

[root@qfusion3 backup]# mysqlbinlog -vv --base64-output=DECODE-ROWS mysql-bin.000002
... ###直接查看最后一个 完整事务event
# at 3719
#190817 21:35:09 server id 2403306 end_log_pos 3791 CRC32 0xf21bb5de Query thread_id=231    exec_time=0 error_code=0
SET TIMESTAMP=1566048909/*!*/;
BEGIN
/*!*/;
# at 3791
#190817 21:35:09 server id 2403306 end_log_pos 3847 CRC32 0x4b1d1af3 Rows_query
# insert into test values(12,'12')
# at 3847
#190817 21:35:09 server id 2403306 end_log_pos 3897 CRC32 0x13e93c21 Table_map: `test`.`test` mapped to number 319
# at 3897
#190817 21:35:09 server id 2403306 end_log_pos 3940 CRC32 0xfbbba83b Write_rows: table id 319 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
### @1=12 /* INT meta=0 nullable=0 is_null=0 */
### @2='12' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
# at 3940
#190817 21:35:09 server id 2403306 end_log_pos 3971 CRC32 0x7ad43e05 Xid = 129705
COMMIT/*!*/; ###可以看到倒数第二个事务是被完整刷入磁盘
# at 3971
#190817 21:35:12 server id 2403306 end_log_pos 4036 CRC32 0x982eaaac GTID last_committed=12 sequence_number=13
SET @@SESSION.GTID_NEXT= '452b51bb-ba7f-11e9-ade9-fa1ee9e22800:14'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 72, event_type: 2
ERROR: Could not read entry at offset 4036: Error in log format or read error.
BEGIN /*added by mysqlbinlog */ /*!*/;
ROLLBACK /* added by mysqlbinlog */ /*!*/; ###最后一个事务没有完整写入磁盘，此处的rollback是mysqlbinlog添加
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 server节点的binlog可以看到最后一个binlog文件大小为4096；解析最后一个binlog文件发现最后一个事务没有完整写入磁盘；与strace追踪对应查看也说明--raw选项下binlog落盘是直到接收字节大小超过4096后，才会调用write()写入到磁盘

⑥、到MySQL server执行flush binary logs；查看binlog server节点的binlog状态

mysql> flush binary logs;
Query OK, 0 rows affected (0.02 sec)

[root@qfusion3 backup]# ll
总用量 12
-rw-r-----. 1 root root 398 8月 12 09:39 mysql-bin.000001
-rw-r-----. 1 root root 4335 8月 12 09:56 mysql-bin.000002
-rw-r-----. 1 root root 0 8月 12 09:56 mysql-bin.000003

手动执行flush binary logs;后，可以发现mysql-bin.000002全部信息写入到磁盘，但是切换后的binlog文件mysql-bin.000003依旧为空。

6.2. binlog server不使用--raw选项

①、登录MySQL创建表结构，查看binlog的信息

mysql> create table test (
    -> id int primary key,
    -> name varchar(10)
    -> );
Query OK, 0 rows affected (0.03 sec)

mysql> flush binary logs;
Query OK, 0 rows affected (0.02 sec)

mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       398 |
| mysql-bin.000002 |       194 |
+------------------+-----------+
2 rows in set (0.01 sec)

②、登录binlog server节点，开启备份binlog进程和strace追踪进程

[root@qfusion3 data]# cd backup/

[root@qfusion3 backup]# ls

###这里对mysqlbinlog加上-vv选项便于后面观看，生产环境慎用
[root@qfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file=/data/backup/backup_log -vv &                   

[root@qfusion3 backup]# ls
backup_binlog

[root@qfusion3 ~]# strace -T -tt -p `pidof mysqlbinlog` -o /root/strace_3.log

③、到MySQL server所在主机，登录MySQL，并插入数据

mysql> insert into test values(1,'1');
Query OK, 1 row affected (0.01 sec)

mysql> insert into test values(2,'2');
Query OK, 1 row affected (0.01 sec)

④、到binlog server节点，查看binlog信息和strace情况

查看strace追踪mysqlbinlog进程情况

... ###查看最后一个事务相关信息
23:07:15.967827 write(3, "# at 477
#190811 23:07:16 server"..., 105) = 105 <0.000011>
23:07:15.967854 recvfrom(4, "B20*/P]!352253$A=21E+Q27327217721"..., 16384, 0, NULL, NULL) = 344 <5.582075>
23:07:21.550048 lseek(3, 0, SEEK_CUR)   = 3554 <0.000020>
23:07:21.550148 write(3, "# at 508
#190811 23:07:22 server"..., 191) = 191 <0.000031>
23:07:21.550218 lseek(3, 0, SEEK_CUR)   = 3745 <0.000008>
23:07:21.550255 write(3, "# at 573
#190811 23:07:22 server"..., 168) = 168 <0.000009>
23:07:21.550290 lseek(3, 0, SEEK_CUR)   = 3913 <0.000008>
23:07:21.550311 write(3, "# at 645
#190811 23:07:22 server"..., 123) = 123 <0.000009>
23:07:21.550345 lseek(3, 0, SEEK_CUR)   = 4036 <0.000008>
23:07:21.550366 write(3, "# at 699
#190811 23:07:22 server"..., 125) = 125 <0.000025>
23:07:21.550418 lseek(3, 0, SEEK_CUR)   = 4161 <0.000008>
23:07:21.550439 write(3, "# at 749
#190811 23:07:22 server"..., 122) = 122 <0.000009>
23:07:21.550462 lseek(3, 0, SEEK_CUR)   = 4283 <0.000008>
23:07:21.550482 write(3, "
BINLOG '
Ki9QXR3qqyQANgAAALsCAA"..., 217) = 217 <0.000008>
23:07:21.550516 lseek(3, 0, SEEK_CUR)   = 4500 <0.000008>
23:07:21.550538 write(3, "### INSERT INTO `test`.`test`
##"..., 149) = 149 <0.000009>
23:07:21.550589 lseek(3, 0, SEEK_CUR)   = 4649 <0.000009>
23:07:21.550612 write(3, "# at 791
#190811 23:07:22 server"..., 105) = 105 <0.000010>

通过strace追踪信息可以看出，binlog server在接收到主库mysqld的binlog的event后会立即调用write()落盘

查看备份binlog内容

[root@qfusion3 backup]# cat backup_log
... ###直接查看最后一个事务event
# at 508
#190811 23:07:22 server id 2403306  end_log_pos 573 CRC32 0x8663bc2f     GTID    last_committed=1    sequence_number=2
SET @@SESSION.GTID_NEXT= '452b51bb-ba7f-11e9-ade9-fa1ee9e22800:3'/*!*/;
# at 573
#190811 23:07:22 server id 2403306  end_log_pos 645 CRC32 0x56f45ca7     Query    thread_id=225    exec_time=0    error_code=0
SET TIMESTAMP=1565536042/*!*/;
BEGIN
/*!*/;
# at 645
#190811 23:07:22 server id 2403306  end_log_pos 699 CRC32 0x5d86dfba     Rows_query
# insert into test values(2,'2')
# at 699
#190811 23:07:22 server id 2403306  end_log_pos 749 CRC32 0xaf89a6f4     Table_map: `test`.`test` mapped to number 317
# at 749
#190811 23:07:22 server id 2403306  end_log_pos 791 CRC32 0xafb005fc     Write_rows: table id 317 flags: STMT_END_F

BINLOG '
Ki9QXR3qqyQANgAAALsCAACAAB5pbnNlcnQgaW50byB0ZXN0IHZhbHVlcygyLCcyJym634Zd
Ki9QXRPqqyQAMgAAAO0CAAAAAD0BAAAAAAEABHRlc3QABHRlc3QAAgMPAh4AAvSmia8=
Ki9QXR7qqyQAKgAAABcDAAAAAD0BAAAAAAEAAgAC//wCAAAAATL8BbCv
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='2' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
# at 791
#190811 23:07:22 server id 2403306  end_log_pos 822 CRC32 0xa0d06710     Xid = 129634
COMMIT/*!*/; ###这里可以看到最后一行数据的commit状态也被备份过来

通过以上解析结果对比可以看到，MySQL 5.7.18版本下不使用--raw选项的binlog server备份的binlog时，主库mysqld的所有提交事务的binlog是被完全备份（最后一个事务的commit语句被实时备份）。

7 | 问题跟踪

查看官方文档是否有bug修复记录

如果使用--raw选项，则不会刷新输出文件，直到进程终止。但是如果还使用--stop-never选项，则进程永远不会终止，因此不会将任何内容写入输出文件。现在每次event后都会刷新输出。

8 | 总结

8.1 上述验证总结

MySQL5.7.19及其以上版本：

mysqlbinlog使用--raw选项时，binlog以原始日志格式记录备份，binlog server会实时备份MySQL server的所有事务（包括最后一个事务的commit语句），并实时写入磁盘；即，使用binlog server备份的binlog做数据恢复时，不会发生数据丢失。
mysqlbinlog不使用--raw选项时，binlog被直接解析为文本格式备份，binlog server会实时备份MySQL server的所有事务（包括最后一个事务的commit语句），并实时写入磁盘；即，使用binlog server备份的binlog做数据恢复时，不会发生数据丢失。

MySQL5.7.18及其以下版本：

mysqlbinlog使用--raw选项时，binlog以原始日志格式备份；binlog server会实时备份MySQL server的所有事务（不包括最后一个事务的commit语句），但是没有实时写入磁盘，待接收binlog的大小超过4K或者4K的倍数时写入磁盘。
mysqlbinlog不使用--raw选项时，binlog被直接解析为文本格式备份；binlog server会实时备份MySQL server的所有事务（不包括最后一个事务的commit语句），并实时写入磁盘；即，使用binlog server备份的binlog做数据恢复时，不会发生数据丢失。

8.2 binlog server优缺点

优点：

MySQL原生远程备份binlog方式，能够做到最大化的实时备份
备份的binlog不会受到主库expire_logs_days和relay_log_purge等参数的影响

缺点：

binlog server是模拟slave的IO线程，所以在主库crash时，存在无法及时同步主库最后一部分数据的风险
需要额外脚本设定删除策略
需要额外安装mysql-client

转自：https://mp.weixin.qq.com/s/MAuXlgkFLPGcSAfP4-Wwvg

螃蟹在剥我的壳，笔记本在写我，漫天的我落在枫叶上雪花上，而你在想我。 --章怀柔