1、背景MySQL包含许多种日志其中包括redo log、undo log、error log、binlog等等其中binlog是区别其他关系型数据库所独有的也是MySQL中最重要的日志之一其作用是用于主备复制、闪回、基于时间点恢复等等本文基于公司产品需求对比研究5.7版本下binlog server备份binlog的功能以及该工具的优缺点。2、测试环境操作系统CentOS 7.4MySQL版本5.7.27/5.7.18数据库关键配置参数log-bin1binlog_formatROWbinlog_row_imageFULLMySQL server10.10.30.243qfusion1binlog server10.10.30.246qfusion33、binlog server原理3.1. 请求方式显式指定一组binlog文件对于每个文件mysqlbinlog连接并发出binlog dump命令。server发送文件完成后断开连接因为mysqlbinlog指定server ID为0。每个文件有一个连接one connection per file。指定开始binlog文件和--to-last-logmysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件完成后断开连接因为mysqlbinlog指定server id为0。指定开始binlog文件和--stop-nevermysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件但在发送最后一个文件后不会断开连接mysqlbinlog指定了非零server ID。注意MySQL从库如果省略server-id默认值0或设置为0则slave拒绝连接到masterERROR] Server id not set, will not start slave for channel 3.2. 工作形态未开启binlog server进程的MySQL主库rootlocalhost : (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节点开启备份进程[rootqfusion3 backup]# mysqlbinlog -R --raw -upowdba -h10.10.30.243 -pxxx --stop-never mysql-bin.000001 --result-file/data/backup/ [1] 4323开启binlog server进程MySQL主库rootlocalhost : (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-filename, -r name此选项指定mysqlbinlog解析的文本存放的位置。当使用--raw选项不使用--result-file时mysqlbinlog会使用从远程mysql server传输的原始binlog格式写入本地文件中默认情况下输出文件与原始日志文件使用相同的文件名称。如果与--raw选项一并使用时--result-file选项值会修改输出文件名的前缀如原本是mysql-bin.000001使用--result-filebinlog则输出文件名为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-idid默认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.275.1. binlog server使用--raw选项使用--raw选项时会以mysqlbinlog连接实例中原始的binlog格式和文件名在执行mysqlbinlog命令的本地系统目录下存放。①、登录MySQL server所在主机创建表结构查看binlog的编号信息rootlocalhost : test 02:23:36 create table test ( - id int primary key, - name varchar(10) - ); Query OK, 0 rows affected (0.03 sec) rootlocalhost : test 02:23:53 flush binary logs; Query OK, 0 rows affected (0.02 sec) rootlocalhost : 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追踪进程[rootqfusion3 ~]# cd /data/backup/ [rootqfusion3 backup]# ls [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file/data/backup/ [rootqfusion3 backup]# ls mysql-bin.000001 mysql-bin.000002 [rootqfusion3 ~]# strace -T -tt -p pidof mysqlbinlog -o /root/strace_0.log③、到MySQL server所在主机登录MySQL并插入数据rootlocalhost : test 02:24:10 insert into test values(1,1); Query OK, 1 row affected (0.01 sec) rootlocalhost : test 02:26:20 insert into test values(2,2); Query OK, 1 row affected (0.00 sec)④、到binlog server所在节点查看binlog信息和strace情况查看strace追踪mysqlbinlog进程情况[rootqfusion3 ~]# 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-50865 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-57372 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-64554 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-69950 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-74942 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-79131通过strace追踪信息可以看出binlog server在接收到主库mysqld的binlog的event后会立即调用write()写入到磁盘。查看备份binlog内容[rootqfusion3 backup]# mysqlbinlog -vv --base64-outputDECODE-ROWS mysql-bin.000002 ... ###直接查看最后一个事务event # at 508 #190811 21:34:03 server id 2433306 end_log_pos 573 CRC32 0x657ee1b7 GTID last_committed1 sequence_number2 rbr_onlyyes /*!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_id11101 exec_time0 error_code0 SET TIMESTAMP1565530443/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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_TYPEOLD_COMPLETION_TYPE*/; /*!50530 SET SESSION.PSEUDO_SLAVE_MODE0*/;通过binlog解析结果对比可以看到MySQL 5.7.27版本下使用--raw选项的binlog server备份的binlog时主库mysqld的所有提交事务的binlog是被完全备份最后一个事务的commit语句被实时备份。3.2. binlog server不使用--raw选项①、登录MySQL server所在主机创建表结构查看binlog的编号信息rootlocalhost : test 02:36:47 create table test ( - id int primary key, - name varchar(10) - ); Query OK, 0 rows affected (0.03 sec) rootlocalhost : test 02:37:02 flush binary logs; Query OK, 0 rows affected (0.02 sec) rootlocalhost : 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追踪进程[rootqfusion3 ~]# cd /data/backup/ [rootqfusion3 backup]# ls ###这里对mysqlbinlog加上-vv选项便于后面观看生产环境慎用 [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file/data/backup/backup_binlog -vv [rootqfusion3 backup]# ls backup_binlog [rootqfusion3 ~]# strace -T -tt -p pidof mysqlbinlog -o /root/strace_1.log③、到MySQL server所在主机登录MySQL并插入数据rootlocalhost : test 02:37:11 insert into test values(1,1); Query OK, 1 row affected (0.01 sec) rootlocalhost : test 02:38:13 insert into test values(2,2); Query OK, 1 row affected (0.01 sec)④、到binlog server所在节点查看binlog信息和strace情况查看strace追踪mysqlbinlog进程情况[rootqfusion3 ~]# 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\240P]!\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内容[rootqfusion3 backup]# cat backup_binlog ... ###直接查看最后一个事务event # at 508 #190811 22:52:16 server id 2433306 end_log_pos 573 CRC32 0x4042ce43 GTID last_committed1 sequence_number2 rbr_onlyyes /*!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_id11101 exec_time0 error_code0 SET TIMESTAMP1565535136/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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.186.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追踪进程[rootqfusion3 data]# cd backup/ [rootqfusion3 backup]# ls [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file/data/backup/ [rootqfusion3 backup]# ls mysql-bin.000001 mysql-bin.000002 [rootqfusion3 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) [rootqfusion1 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进程情况[rootqfusion3 ~]# 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\1EQ\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\1EQ\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内容[rootqfusion3 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进程情况[rootqfusion3 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\1EQ\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内容[rootqfusion3 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 [rootqfusion3 backup]# mysqlbinlog -vv --base64-outputDECODE-ROWS mysql-bin.000002 ... ###直接查看最后一个 完整事务event # at 3719 #190817 21:35:09 server id 2403306 end_log_pos 3791 CRC32 0xf21bb5de Query thread_id231 exec_time0 error_code0 SET TIMESTAMP1566048909/*!*/; 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 ### 112 /* INT meta0 nullable0 is_null0 */ ### 212 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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_committed12 sequence_number13 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_TYPEOLD_COMPLETION_TYPE*/; /*!50530 SET SESSION.PSEUDO_SLAVE_MODE0*/;查看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) [rootqfusion3 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追踪进程[rootqfusion3 data]# cd backup/ [rootqfusion3 backup]# ls ###这里对mysqlbinlog加上-vv选项便于后面观看生产环境慎用 [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file/data/backup/backup_log -vv [rootqfusion3 backup]# ls backup_binlog [rootqfusion3 ~]# 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进程情况[root10-10-30-238 ~]# cat strace_3.log ... ###查看最后一个事务相关信息 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\1EQ\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内容[rootqfusion3 backup]# cat backup_log ... ###直接查看最后一个事务event # at 508 #190811 23:07:22 server id 2403306 end_log_pos 573 CRC32 0x8663bc2f GTID last_committed1 sequence_number2 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_id225 exec_time0 error_code0 SET TIMESTAMP1565536042/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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-client9、参考资料官方文档https://dev.mysql.com/doc/refman/5.7/en/mysqlbinlog-backup.htmlstrace工具参考知数堂https://ke.qq.com/course/384101bug修复链接https://dev.mysql.com/doc/relno
MySQL binlog server详解
发布时间：2026/6/5 13:51:12
1、背景MySQL包含许多种日志其中包括redo log、undo log、error log、binlog等等其中binlog是区别其他关系型数据库所独有的也是MySQL中最重要的日志之一其作用是用于主备复制、闪回、基于时间点恢复等等本文基于公司产品需求对比研究5.7版本下binlog server备份binlog的功能以及该工具的优缺点。2、测试环境操作系统CentOS 7.4MySQL版本5.7.27/5.7.18数据库关键配置参数log-bin1binlog_formatROWbinlog_row_imageFULLMySQL server10.10.30.243qfusion1binlog server10.10.30.246qfusion33、binlog server原理3.1. 请求方式显式指定一组binlog文件对于每个文件mysqlbinlog连接并发出binlog dump命令。server发送文件完成后断开连接因为mysqlbinlog指定server ID为0。每个文件有一个连接one connection per file。指定开始binlog文件和--to-last-logmysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件完成后断开连接因为mysqlbinlog指定server id为0。指定开始binlog文件和--stop-nevermysqlbinlog连接并为所有binlog文件发出binlog dump命令。server发送所有文件但在发送最后一个文件后不会断开连接mysqlbinlog指定了非零server ID。注意MySQL从库如果省略server-id默认值0或设置为0则slave拒绝连接到masterERROR] Server id not set, will not start slave for channel 3.2. 工作形态未开启binlog server进程的MySQL主库rootlocalhost : (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节点开启备份进程[rootqfusion3 backup]# mysqlbinlog -R --raw -upowdba -h10.10.30.243 -pxxx --stop-never mysql-bin.000001 --result-file/data/backup/ [1] 4323开启binlog server进程MySQL主库rootlocalhost : (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-filename, -r name此选项指定mysqlbinlog解析的文本存放的位置。当使用--raw选项不使用--result-file时mysqlbinlog会使用从远程mysql server传输的原始binlog格式写入本地文件中默认情况下输出文件与原始日志文件使用相同的文件名称。如果与--raw选项一并使用时--result-file选项值会修改输出文件名的前缀如原本是mysql-bin.000001使用--result-filebinlog则输出文件名为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-idid默认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.275.1. binlog server使用--raw选项使用--raw选项时会以mysqlbinlog连接实例中原始的binlog格式和文件名在执行mysqlbinlog命令的本地系统目录下存放。①、登录MySQL server所在主机创建表结构查看binlog的编号信息rootlocalhost : test 02:23:36 create table test ( - id int primary key, - name varchar(10) - ); Query OK, 0 rows affected (0.03 sec) rootlocalhost : test 02:23:53 flush binary logs; Query OK, 0 rows affected (0.02 sec) rootlocalhost : 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追踪进程[rootqfusion3 ~]# cd /data/backup/ [rootqfusion3 backup]# ls [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file/data/backup/ [rootqfusion3 backup]# ls mysql-bin.000001 mysql-bin.000002 [rootqfusion3 ~]# strace -T -tt -p pidof mysqlbinlog -o /root/strace_0.log③、到MySQL server所在主机登录MySQL并插入数据rootlocalhost : test 02:24:10 insert into test values(1,1); Query OK, 1 row affected (0.01 sec) rootlocalhost : test 02:26:20 insert into test values(2,2); Query OK, 1 row affected (0.00 sec)④、到binlog server所在节点查看binlog信息和strace情况查看strace追踪mysqlbinlog进程情况[rootqfusion3 ~]# 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-50865 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-57372 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-64554 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-69950 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-74942 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-79131通过strace追踪信息可以看出binlog server在接收到主库mysqld的binlog的event后会立即调用write()写入到磁盘。查看备份binlog内容[rootqfusion3 backup]# mysqlbinlog -vv --base64-outputDECODE-ROWS mysql-bin.000002 ... ###直接查看最后一个事务event # at 508 #190811 21:34:03 server id 2433306 end_log_pos 573 CRC32 0x657ee1b7 GTID last_committed1 sequence_number2 rbr_onlyyes /*!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_id11101 exec_time0 error_code0 SET TIMESTAMP1565530443/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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_TYPEOLD_COMPLETION_TYPE*/; /*!50530 SET SESSION.PSEUDO_SLAVE_MODE0*/;通过binlog解析结果对比可以看到MySQL 5.7.27版本下使用--raw选项的binlog server备份的binlog时主库mysqld的所有提交事务的binlog是被完全备份最后一个事务的commit语句被实时备份。3.2. binlog server不使用--raw选项①、登录MySQL server所在主机创建表结构查看binlog的编号信息rootlocalhost : test 02:36:47 create table test ( - id int primary key, - name varchar(10) - ); Query OK, 0 rows affected (0.03 sec) rootlocalhost : test 02:37:02 flush binary logs; Query OK, 0 rows affected (0.02 sec) rootlocalhost : 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追踪进程[rootqfusion3 ~]# cd /data/backup/ [rootqfusion3 backup]# ls ###这里对mysqlbinlog加上-vv选项便于后面观看生产环境慎用 [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file/data/backup/backup_binlog -vv [rootqfusion3 backup]# ls backup_binlog [rootqfusion3 ~]# strace -T -tt -p pidof mysqlbinlog -o /root/strace_1.log③、到MySQL server所在主机登录MySQL并插入数据rootlocalhost : test 02:37:11 insert into test values(1,1); Query OK, 1 row affected (0.01 sec) rootlocalhost : test 02:38:13 insert into test values(2,2); Query OK, 1 row affected (0.01 sec)④、到binlog server所在节点查看binlog信息和strace情况查看strace追踪mysqlbinlog进程情况[rootqfusion3 ~]# 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\240P]!\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内容[rootqfusion3 backup]# cat backup_binlog ... ###直接查看最后一个事务event # at 508 #190811 22:52:16 server id 2433306 end_log_pos 573 CRC32 0x4042ce43 GTID last_committed1 sequence_number2 rbr_onlyyes /*!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_id11101 exec_time0 error_code0 SET TIMESTAMP1565535136/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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.186.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追踪进程[rootqfusion3 data]# cd backup/ [rootqfusion3 backup]# ls [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --raw --stop-never mysql-bin.000001 --result-file/data/backup/ [rootqfusion3 backup]# ls mysql-bin.000001 mysql-bin.000002 [rootqfusion3 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) [rootqfusion1 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进程情况[rootqfusion3 ~]# 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\1EQ\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\1EQ\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内容[rootqfusion3 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进程情况[rootqfusion3 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\1EQ\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内容[rootqfusion3 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 [rootqfusion3 backup]# mysqlbinlog -vv --base64-outputDECODE-ROWS mysql-bin.000002 ... ###直接查看最后一个 完整事务event # at 3719 #190817 21:35:09 server id 2403306 end_log_pos 3791 CRC32 0xf21bb5de Query thread_id231 exec_time0 error_code0 SET TIMESTAMP1566048909/*!*/; 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 ### 112 /* INT meta0 nullable0 is_null0 */ ### 212 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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_committed12 sequence_number13 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_TYPEOLD_COMPLETION_TYPE*/; /*!50530 SET SESSION.PSEUDO_SLAVE_MODE0*/;查看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) [rootqfusion3 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追踪进程[rootqfusion3 data]# cd backup/ [rootqfusion3 backup]# ls ###这里对mysqlbinlog加上-vv选项便于后面观看生产环境慎用 [rootqfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file/data/backup/backup_log -vv [rootqfusion3 backup]# ls backup_binlog [rootqfusion3 ~]# 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进程情况[root10-10-30-238 ~]# cat strace_3.log ... ###查看最后一个事务相关信息 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\1EQ\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内容[rootqfusion3 backup]# cat backup_log ... ###直接查看最后一个事务event # at 508 #190811 23:07:22 server id 2403306 end_log_pos 573 CRC32 0x8663bc2f GTID last_committed1 sequence_number2 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_id225 exec_time0 error_code0 SET TIMESTAMP1565536042/*!*/; 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 ### 12 /* INT meta0 nullable0 is_null0 */ ### 22 /* VARSTRING(30) meta30 nullable1 is_null0 */ # 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-client9、参考资料官方文档https://dev.mysql.com/doc/refman/5.7/en/mysqlbinlog-backup.htmlstrace工具参考知数堂https://ke.qq.com/course/384101bug修复链接https://dev.mysql.com/doc/relno
