binlog server还是不可靠吗？

深藏阁楼爱情的钟 2024-04-17 05:39 54阅读 0赞

### **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主库

*  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主库

*  可以看到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, 
    "B\0\0\20\0K\31P]!\32!%\0A\0\0\0=\2\0\0\0\0\0\303\312v\202\242\30\21"..., 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, "K\31P]!\32!%\0A\0\0\0=\2\0\0\0\0\0\303\312v\202\242\30\21\351\237\302\372\342"..., 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, "K\31P]\2\32!%\0H\0\0\0\205\2\0\0\10\0]+\0\0\0\0\0\0\4\0\0\32\0"..., 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, "K\31P]\35\32!%\0006\0\0\0\273\2\0\0\200\0\36insert 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, "K\31P]\23\32!%\0002\0\0\0\355\2\0\0\0\0.\3\0\0\0\0\1\0\4test"..., 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, "K\31P]\36\32!%\0*\0\0\0\27\3\0\0\0\0.\3\0\0\0\0\1\0\2\0\2\377\374"..., 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, "K\31P]\20\32!%\0\37\0\0\0006\3\0\0\0\0\252\353;\0\0\0\0\0\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\n#190811 22:52:10 server"..., 106) = 106 <0.000005>
    22:52:15.944181 recvfrom(4, 
    "B\0\0\20\0\240+P]!\32!%\0A\0\0\0=\2\0\0\0\0\0\303\312v\202\242\30\21"..., 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\n#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\n#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\n#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\n#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\n#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, "\nBINLOG '\noCtQXR0aISUANgAAALsCAA"..., 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`\n##"..., 149) = 149 <0.000007>
    22:52:22.207663 lseek(3, 0, SEEK_CUR)   = 4824 <0.000022>
    22:52:22.207723 write(3, "# at 791\n#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\0\0\n\0\201\303P]!\352\253$\0A\0\0\0\3\1\0\0\0\0\1E+Q\273\272\177\21"..., 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,
    "B\0\0\20\0\210\303P]!\352\253$\0A\0\0\0=\2\0\0\0\0\1E+Q\273\272\177\21"..., 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, "B\0\0R\0\211\305P]!\352\253$\0A\0\0\0\304\17\0\0\0\0\1E+Q\273\272\177\21"..., 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, "\376bin\354\302P]\17\352\253$\0w\0\0\0{\0\0\0\0\0\4\0005.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的信息

②、登录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\n#190811 23:07:16 server"..., 105) = 105 <0.000011>
    23:07:15.967854 recvfrom(4, "B\0\0\20\0*/P]!\352\253$\0A\0\0\0=\2\0\0\0\0\1E+Q\273\272\177\21"..., 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\n#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\n#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\n#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\n#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\n#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, "\nBINLOG '\nKi9QXR3qqyQANgAAALsCAA"..., 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`\n##"..., 149) = 149 <0.000009>
    23:07:21.550589 lseek(3, 0, SEEK_CUR)   = 4649 <0.000009>
    23:07:21.550612 write(3, "# at 791\n#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修复记录

![format_png][]

如果使用--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://dev.mysql.com/doc/refman/5.7/en/mysqlbinlog-backup.html

strace工具参考知数堂：https://ke.qq.com/course/384101

bug修复链接：https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-19.html

### **| 作者简介** ###

### **岳雷·沃趣科技数据库工程师** ###

熟悉MySQL体系结构和innodb存储引擎工作原理；以及MySQL备份恢复、复制、数据迁移等技术；专注于MySQL、MariaDB开源数据库，喜好开源技术。

[format_png]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy85UmpScnZPNjN6ZGNOSkNrUzBuRGtWcWpsVGdTWjl6MGIyQUppYTc3TDhpYmU5eTZoSmt2aWFUbFBYZWlhTVc1U3ZIN3ptSmZhZFBOcHhNa3Qyc2V0cUY2MkEvNjQwP3d4X2ZtdD1wbmcmdHA9d2VicCZ3eGZyb209NSZ3eF9sYXp5PTEmd3hfY289MQ?x-oss-process=image/format,png