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

①、登入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的資訊

mysql> create table test (
    -> id int primary key,
    -> name varchar(10)
    -> );
Query OK, 0 rows affected (0.03 sec)
mysql> flush binary logs;
Query OK, 0 rows affected (0.02 sec)
mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       398 |
| mysql-bin.000002 |       194 |
+------------------+-----------+
2 rows in set (0.01 sec)

②、登入binlog server節點，開啟備份binlog程式和strace追蹤程式

root@qfusion3 data]# cd backup/
[root@qfusion3 backup]# ls
###這裡對mysqlbinlog加上-vv選項便於後面觀看，生產環境慎用
[root@qfusion3 backup]# mysqlbinlog -upowdba -h10.10.30.243 -pabc123 -R --stop-never mysql-bin.000001 --result-file=/data/backup/backup_log -vv &                   
[root@qfusion3 backup]# ls
backup_binlog
[root@qfusion3 ~]# strace -T -tt -p `pidof mysqlbinlog` -o /root/strace_3.log

③、到MySQL server所在主機，登入MySQL，並插入資料

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

④、到binlog server節點，檢視binlog資訊和strace情況

• 檢視strace追蹤mysqlbinlog程式情況

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

• 檢視備份binlog內容

[root@qfusion3 backup]# cat backup_log
... ###直接檢視最後一個事務event
# at 508
#190811 23:07:22 server id 2403306  end_log_pos 573 CRC32 0x8663bc2f     GTID    last_committed=1    sequence_number=2
SET @@SESSION.GTID_NEXT= '452b51bb-ba7f-11e9-ade9-fa1ee9e22800:3'/*!*/;
# at 573
#190811 23:07:22 server id 2403306  end_log_pos 645 CRC32 0x56f45ca7     Query    thread_id=225    exec_time=0    error_code=0
SET TIMESTAMP=1565536042/*!*/;
BEGIN
/*!*/;
# at 645
#190811 23:07:22 server id 2403306  end_log_pos 699 CRC32 0x5d86dfba     Rows_query
# insert into test values(2,'2')
# at 699
#190811 23:07:22 server id 2403306  end_log_pos 749 CRC32 0xaf89a6f4     Table_map: `test`.`test` mapped to number 317
# at 749
#190811 23:07:22 server id 2403306  end_log_pos 791 CRC32 0xafb005fc     Write_rows: table id 317 flags: STMT_END_F
BINLOG '
Ki9QXR3qqyQANgAAALsCAACAAB5pbnNlcnQgaW50byB0ZXN0IHZhbHVlcygyLCcyJym634Zd
Ki9QXRPqqyQAMgAAAO0CAAAAAD0BAAAAAAEABHRlc3QABHRlc3QAAgMPAh4AAvSmia8=
Ki9QXR7qqyQAKgAAABcDAAAAAD0BAAAAAAEAAgAC//wCAAAAATL8BbCv
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=2 /* INT meta=0 nullable=0 is_null=0 */
###   @2='2' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
# at 791
#190811 23:07:22 server id 2403306  end_log_pos 822 CRC32 0xa0d06710     Xid = 129634
COMMIT/*!*/; ###這裡可以看到最後一行資料的commit狀態也被備份過來

• 透過以上解析結果對比可以看到，MySQL 5.7.18版本下不使用--raw選項的binlog server備份的binlog時，主庫mysqld的所有提交事務的binlog是被完全備份（最後一個事務的commit語句被實時備份）。

7、問題跟蹤

• 檢視官方文件是否有bug修復記錄

• 如果使用--raw選項，則不會重新整理輸出檔案，直到程式終止。但是如果還使用--stop-never選項，則程式永遠不會終止，因此不會將任何內容寫入輸出檔案。現在每次event後都會重新整理輸出。

8、總結

8.1 上述驗證總結

• MySQL5.7.19及其以上版本：
  
  • mysqlbinlog使用--raw選項時，binlog以原始日誌格式記錄備份，binlog server會實時備份MySQL server的所有事務（包括最後一個事務的commit語句），並實時寫入磁碟；即，使用binlog server備份的binlog做資料恢復時，不會發生資料丟失。
  • mysqlbinlog不使用--raw選項時，binlog被直接解析為文字格式備份，binlog server會實時備份MySQL server的所有事務（包括最後一個事務的commit語句），並實時寫入磁碟；即，使用binlog server備份的binlog做資料恢復時，不會發生資料丟失。
• MySQL5.7.18及其以下版本：
  
  • mysqlbinlog使用--raw選項時，binlog以原始日誌格式備份；binlog server會實時備份MySQL server的所有事務（不包括最後一個事務的commit語句），但是沒有實時寫入磁碟，待接收binlog的大小超過4K或者4K的倍數時寫入磁碟。
  • mysqlbinlog不使用--raw選項時，binlog被直接解析為文字格式備份；binlog server會實時備份MySQL server的所有事務（不包括最後一個事務的commit語句），並實時寫入磁碟；即，使用binlog server備份的binlog做資料恢復時，不會發生資料丟失。

8.2 binlog server優缺點

• 優點：
  • MySQL原生遠端備份binlog方式，能夠做到最大化的實時備份
  • 備份的binlog不會受到主庫expire_logs_days和relay_log_purge等引數的影響
• 缺點：
  • binlog server是模擬slave的IO執行緒，所以在主庫crash時，存在無法及時同步主庫最後一部分資料的風險
  • 需要額外指令碼設定刪除策略
  • 需要額外安裝mysql-client

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