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如下：

好了简单记录