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，并插入資料

root@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語句被實時備份）。

3.2. binlog server不使用--raw選項

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

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)

[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()寫入到磁盤

[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選項

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)

[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> 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情況

[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()寫入到磁盤

[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的資訊

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)

[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> 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@10-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\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()落盤

[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

9、參考資料

官方文檔： 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

binlog server還是不靠譜嗎？

1、背景

2、測試環境

3、binlog server原理

3.1. 請求方式

3.2. 工作形态

4、binlog server重要參數

5、binlog server驗證（MySQL5.7.27）

5.1. binlog server使用--raw選項

3.2. binlog server不使用--raw選項

6、binlog server驗證（MySQL5.7.18）

6.1. binlog server使用--raw選項

6.2. binlog server不使用--raw選項

7、問題跟蹤

8、總結

8.1 上述驗證總結

8.2 binlog server優缺點

9、參考資料

繼續閱讀

2022秋招面試總結（cpp+java+測開）百度測開一面位元組後端一面蝦皮後端一面蝦皮後端二面

資料庫之DDL操作資料庫DDL操作資料庫DDL操作資料表

資料庫之DQL操作資料庫

mysql優化（sql優化）

資料遷移方法資料遷移原則資料遷移之雙寫方案資料遷移之級聯同步方案

redis叢集資料一緻性_RedisRaft為Redis叢集帶來強大的資料一緻性

寶塔面闆mysql恢複2018.1.8更新

Centos7 MySQL 5.7 安裝MySQL 5.7 安裝

查找入職員工時間排名倒數第三的員工所有資訊

Hibernate使用Hibernate的“3個準備，7個步驟”Hibernate API簡介操作實體對象對象識别

雲計算面試題——mysql/存儲引擎/備份

SQL語言基礎：常用的資料查詢語句

Ubuntu16.04安裝Apache+MySQL+PHP1. 安裝Apache2. 安裝MySQL3. 安裝PHP4. 安裝phpMyAdmin

MySQL的4種隔離級别？出現問題

neo4j之cypher使用文檔

mysql使用source指令導入.sql檔案