MySQL：從庫binlog 使用mysqlbinlog stop-datetime過濾問題

更多主從同步相關可以參考我的《深入了解MySQL主從原理》專欄：

本文是一個朋友問我問題。從庫使用mysqlbinlog --stop-datetime 的時候沒有想要的記錄。

本文簡單記錄這個問題：如果從庫log_slave_updates開啟，那麼從庫需要記錄從庫應用的Event，有如下特點：

• 從庫binlog記錄的應用主庫的Event，其Event header timestamp是主庫的時間。
• 從庫binlog記錄本地執行個體的Event，其Event header timestamp則是本地執行個體的時間。
• 從庫binlog的format event和p gtid event則是本地實際的時間。

一、構造這樣的binlog

# at 4
#190825  0:01:37 server id 953340  end_log_pos 123 CRC32 0x9409b3c9     Start: binlog v 4, server v 5.7.22-22-debug-log created 190825  0:01:37
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
YV9hXQ/8iw4AdwAAAHsAAAABAAQANS43LjIyLTIyLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AcmzCZQ=
'/*!*/;
# at 123
#190825  0:01:37 server id 953340  end_log_pos 234 CRC32 0x483a41ac     Previous-GTIDs
# 010fde77-2075-11e9-ba07-5254009862c0:16-40,
# cb7ea36e-670f-11e9-b483-5254008138e4:94-104
# at 234
#190724 14:07:36 server id 413340  end_log_pos 299 CRC32 0x9294741b     GTID    last_committed=0        sequence_number=1       rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'cb7ea36e-670f-11e9-b483-5254008138e4:105'/*!*/;
# at 299
#190724 14:07:36 server id 413340  end_log_pos 362 CRC32 0x23ecd791     Query   thread_id=5     exec_time=2714050       error_code=0
SET TIMESTAMP=1563948456/*!*/;
SET @@session.pseudo_thread_id=5/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=524288/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=83,@@session.collation_connection=83,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 362
#190724 14:07:36 server id 413340  end_log_pos 414 CRC32 0x65673dab     Table_map: `testmts`.`testwq` mapped to number 110
# at 414
#190724 14:07:36 server id 413340  end_log_pos 454 CRC32 0xa368ded1     Write_rows: table id 110 flags: STMT_END_F

BINLOG '
qPU3XROcTgYANAAAAJ4BAAAAAG4AAAAAAAEAB3Rlc3RtdHMABnRlc3R3cQABAwABqz1nZQ==
qPU3XR6cTgYAKAAAAMYBAAAAAG4AAAAAAAEAAgAB//4KAAAA0d5oow==
'/*!*/;
# at 454
#190724 14:07:36 server id 413340  end_log_pos 485 CRC32 0x40df9d14     Xid = 44
COMMIT/*!*/;

           

這個binlog是從庫的binlog，Event header timestamp如下：

• FORMAT_DESCRIPTION_EVENT：190825 0:01:37
• PREVIOUS_GTIDS_LOG_EVENT：190825 0:01:37

以上兩個Event都是從庫binlog自己生成當然就是本執行個體的時間。

• GTID_LOG_EVENT：190724 14:07:36
• QUERY_EVENT：190724 14:07:36
• MAP_EVENT：190724 14:07:36
• WRITE_EVET：190724 14:07:36
• XID_EVENT：190724 14:07:36

他們都是主庫語句指令發起的時間。

如果這個時候我們使用stop-datetime=‘2019-07-25 00:00:00’ 不會解析到這個事務。原因在于FORMAT_DESCRIPTION_EVENT的時間超過了這個時間直接退出了。

源碼如下：

debug如下：

好了簡單記錄