热门搜索:
您现在的位置是：首页 > 文章详情

详解 MySQL 的 binlog 时间戳与 exec_time 的关系

日期：2024-05-14点击：194

详解 binlog 时间戳与 exec_time 的关系。

作者：李锡超，苏商银行DBA，负责数据库和中间件运维和建设。擅长 MySQL、Python、Oracle，爱好骑行、技术研究和分享。

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文约 2000 字，预计阅读需要 8 分钟。

概述

近期，某系统进行测试时，发现主从同步存在延迟，随即通过 binlog 确认延迟原因。当使用 mysqlbinlog 命令解析后，发现其中的信息“似懂非懂”。

例如，对于如下 binlog 片段：

# at 449880 #240430 18:38:49 server id 345 end_log_pos 449967 CRC32 0xb3e8a02a GTID last_committed=13 sequence_number=14 rbr_only=yes original_committed_timestamp=1714473533138376 immediate_commit_timestamp=1714473539246294 transaction_length=446792 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; # original_commit_timestamp=1714473533138376 (2024-04-30 18:38:53.138376 CST) # immediate_commit_timestamp=1714473539246294 (2024-04-30 18:38:59.246294 CST) /*!80001 SET @@session.original_commit_timestamp=1714473533138376*//*!*/; /*!80014 SET @@session.original_server_version=80027*//*!*/; /*!80014 SET @@session.immediate_server_version=80027*//*!*/; SET @@SESSION.GTID_NEXT= 'c0ac4587-6046-11ee-9fa7-001c42c92a7b:44'/*!*/; # at 449967 #240430 18:38:16 server id 345 end_log_pos 450039 CRC32 0x0c7cb74e Query thread_id=16 exec_time=37 error_code=0 SET TIMESTAMP=1714473496/*!*/; BEGIN /*!*/; /*!*/; # at 450039 #240430 18:38:16 server id 345 end_log_pos 450098 CRC32 0xf9a84808 Table_map: `testdb`.`tb3` mapped to number 110 # at 450098 #240430 18:38:16 server id 345 end_log_pos 458309 CRC32 0xad84e9b0 Write_rows: table id 110 ... # at 896439 #240430 18:38:46 server id 345 end_log_pos 896498 CRC32 0x5cd7cd3b Table_map: `testdb`.`tb3` mapped to number 110 # at 896498 #240430 18:38:46 server id 345 end_log_pos 896540 CRC32 0x21b77031 Write_rows: table id 110 flags: STMT_END_F ... ### INSERT INTO `testdb`.`tb3` ### SET ### @1=131060 /* INT meta=0 nullable=0 is_null=0 */ ### @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */ # at 896540 #240430 18:38:49 server id 345 end_log_pos 896599 CRC32 0x6d6bf911 Table_map: `testdb`.`tb3` mapped to number 110 # at 896599 #240430 18:38:49 server id 345 end_log_pos 896641 CRC32 0xccd2fbb1 Write_rows: table id 110 flags: STMT_END_F ... ### INSERT INTO `testdb`.`tb3` ### SET ### @1=131061 /* INT meta=0 nullable=0 is_null=0 */ ### @2='c' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */ # at 896641 #240430 18:38:49 server id 345 end_log_pos 896672 CRC32 0xadb14b9d Xid = 85

通过以上 binlog 可知（P1）：

#240430 18:38:16 执行 begin 开启了事务 （为便于表述，将时间字段名为timestamp） #240430 18:38:16 执行了 tb3的insert 操作 #240430 18:38:46 执行了 tb3的insert 操作 #240430 18:38:49 执行了 tb3的insert 操作 #240430 18:38:49 执行了commit操作

此外（P2）：

original_commit_timestamp=2024-04-30 18:38:53 immediate_commit_timestamp=2024-04-30 18:38:59 exec_time=37

针对 P2 信息，提出如下问题：

  • Q1：P2 中的字段分别表示什么意思？是如何计算的？
  • Q2：P2 的字段和 P1 看到的 timestamp 有什么关系呢？
  • Q4：P1 中的 timestamp 是如何取值的？特别是主从环境下

为此，通过测试验证，并结合源码分析 binlog 中常见 Event 时间与 exec_time 的由来，并总结字段之间的关系。

以下分析基于 MySQL 8.0，不同版本字段可能不同。

主节点 binlog 日志

1. GTID Event

timestamp

对于主节点：如没有特殊说明，Event 的 timestamp 是在每个线程执行 dispatch_command() 初始位置获取最新时间戳（thd->start_time），并在生产 Event 对象时将 thd->start_time 赋值到 Log_event::common_header->when。

主要堆栈信息如下：

|-handle_connection (./sql/conn_handler/connection_handler_per_thread.cc:302) |-do_command (./sql/sql_parse.cc:1343) |-dispatch_command (./sql/sql_parse.cc:1922) // 设置 thd->start_time |-thd->set_time() |-my_micro_time_to_timeval(start_utime, &start_time) |-dispatch_sql_command (./sql/sql_parse.cc:5135) |-mysql_execute_command (./sql/sql_parse.cc:3518) |-Sql_cmd_dml::execute (./sql/sql_select.cc:579) …… |-Table_map_log_event the_event(this, table, table->s->table_map_id,is_transactional) …… |-Rows_log_event *const ev = new RowsEventT(this, table, table->s->table_map_id, ) …… |-Xid_log_event end_evt(thd, xid)

immediate_commit_timestamp/original_commit_timestamp

immediate_commit_timestamp 获取即为提交时刻的时间戳，主节点 original_commit_timestamp 等于 immediate_commit_timestamp。

|-error = trx_cache.flush(thd, &trx_bytes, wrote_xid) |-Transaction_ctx *trn_ctx = thd->get_transaction() |-trn_ctx->sequence_number = mysql_bin_log.m_dependency_tracker.step() |-if (trn_ctx->last_committed == SEQ_UNINIT): trn_ctx->last_committed = trn_ctx->sequence_number - 1 |-if (!error): if ((error = mysql_bin_log.write_transaction(thd, this, &writer))) |-int64 sequence_number, last_committed |-m_dependency_tracker.get_dependency(thd, sequence_number, last_committed) |-thd->get_transaction()->last_committed = SEQ_UNINIT |-ulonglong immediate_commit_timestamp = my_micro_time() //|-ulonglong original_commit_timestamp = thd->variables.original_commit_timestamp |-ulonglong original_commit_timestamp = immediate_commit_timestamp |-uint32_t trx_immediate_server_version = do_server_version_int(::server_version) |-Gtid_log_event gtid_event(thd, cache_data->is_trx_cache(), last_committed, sequence_number, cache_data->may_have_sbr_stmts(), original_commit_timestamp, immediate_commit_timestamp, trx_original_server_version, trx_immediate_server_version)

2. BEGIN Event

timestamp

注意：对于主节点 BEGIN event 的 timestamp 并不是执行 BEGIN 时的时间戳，而是执行第一个修改操作。在完成 InnoDB 层第一行数据修改之后，生成并写入 Table_map event。在生成 Table_map event 之前，如果此时整个事务的 binlog 缓存是空的，才会立即获取该操作的 thd->start_time，并生成真正的 BEGIN event。

exec_time

同时，对于主节点的 exec_time 就是在生成 BEGIN Event 的过程中，获取最新的时间戳 - BEGIN Event 的 timestamp 而得。

exec_time = A - B

  • A：执行第一个修改 SQL，完成第一行修改（write/update/delete）操作后，生成 BEGIN Event 的时间。
  • B：第一个修改 SQL 的开始执行时间（thd->start_time）

内部堆栈与执行顺序如下：

3. Table_map Event

4. Write Event

5. Xid Event

6. 主节点小结

  • 除了 BEGIN Event 的 timestamp 是第一个需要写入 binlog 操作（如：write/update/delete）的开始时间；
  • 其它 Event 的 timestamp 为 SQL 语句执行时的开始时间；
  • immediate_commit_timestamp/original_commit_timestamp 即为提交时的时间戳；
  • exec_time = A - B
    • A：执行第一个修改 SQL，完成第一行修改（write/update/delete）操作后，生成 BEGIN Event 的时间。
    • B：第一个修改 SQL 的开始执行时间（thd->start_time）

从节点 binlog 日志

1. GTID Event

timestamp

在从节点：对于 GTID Event，MySQL 在解析 Event 时，并不会获取主节点 GTID/XID Event 的时间戳，因此会“继承”该事务上一个操作的时间戳。而从节点所有修改操作的时间戳都来自于主节点执行操作时的时间戳。因此从节点的 GTID/XID Event 的时间即为主节点最后一个修改操作的 timestamp。

immediate_commit_timestamp/original_commit_timestamp

immediate_commit_timestamp 获取从节点提交时刻的时间戳。original_commit_timestamp 从 GTID Event 中的 original_commit_timestamp 获取，即为主节点提交操作的 timestamp。

主要堆栈信息如下：

|-handle_slave_worker (./sql/rpl_replica.cc:5891) |-slave_worker_exec_job_group (./sql/rpl_rli_pdb.cc:2549) |-Slave_worker::slave_worker_exec_event (./sql/rpl_rli_pdb.cc:1760) |-Xid_apply_log_event::do_apply_event_worker (./sql/log_event.cc:6179) |-Xid_log_event::do_commit (./sql/log_event.cc:6084) |-trans_commit (./sql/transaction.cc:246) |-ha_commit_trans (./sql/handler.cc:1765) |-MYSQL_BIN_LOG::commit (./sql/binlog.cc:8170) |-MYSQL_BIN_LOG::ordered_commit (./sql/binlog.cc:8789) |-MYSQL_BIN_LOG::process_flush_stage_queue (./sql/binlog.cc:8326) |-MYSQL_BIN_LOG::flush_thread_caches (./sql/binlog.cc:8218) |-binlog_cache_mngr::flush (./sql/binlog.cc:1099) |-binlog_cache_data::flush (./sql/binlog.cc:2098) |-MYSQL_BIN_LOG::write_transaction (./sql/binlog.cc:1586) // 生成并写入 GTID event |-ulonglong immediate_commit_timestamp = my_micro_time() |-if (original_commit_timestamp == UNDEFINED_COMMIT_TIMESTAMP){...} |-Gtid_log_event gtid_event(thd, cache_data->is_trx_cache(), last_committed, sequence_number, cache_data->may_have_sbr_stmts(), original_commit_timestamp, immediate_commit_timestamp, trx_original_server_version, trx_immediate_server_version)

公式

immediate_commit_timestamp - original_commit_timestamp = A + B + C

  • A = 主节点 传输 binlog 到 从节点 的耗时
  • B = 从节点 重放 binlog 的耗时
  • C = 同步延迟/中断的耗时

2. BEGIN Event

timestamp

这里的 timestamp 来自于主节点 BEGIN Event 的 timestamp。其实际执行时，是会获取 BEGIN Event 的 timestamp 将其赋值给 thd->start_time/thd->user_time。从节点生成 Event 对象时，继续从 thd->start_time 获取时间戳即可。

exec_time

然后，从节点的 exec_time 依然是生成 BEGIN Event 的过程中，获取 最新的时间戳 - timestamp 而得到（注意这里的 timestamp 来自于主节点修改 SQL 的开始执行时间）。

主要堆栈信息如下：

|-handle_slave_worker (./sql/rpl_replica.cc:5891) |-slave_worker_exec_job_group (./sql/rpl_rli_pdb.cc:2549) |-Slave_worker::slave_worker_exec_event (./sql/rpl_rli_pdb.cc:1760) |-Log_event::do_apply_event_worker (./sql/log_event.cc:1083) |-Query_log_event::do_apply_event (./sql/log_event.cc:4443) |-Query_log_event::do_apply_event (./sql/log_event.cc:4606) // 设置 user_time=start_time=ev.common_header->when |-thd->set_time(&(common_header->when)) // query_arg="BEGIN" |-thd->set_query(query_arg, q_len_arg) ...

公式

exec_time = A + B + C + D

  • A = 主节点 整个事务的耗时
  • B = binlog 传输耗时
  • C = 同步延迟/中断耗时（可能-主要）
  • D = 从节点完成第一行数据修改

original_commit_timestamp - begin event 的 timestamp = 表示主节点整个事务的实际耗时（【主-第一个修改】 到【主- commit 开始】）。

3. Table_map Event

4. Write Event

5. Xid Event

6. 从节点小节

  • 除了 GTID/XID Event，其它 Event 的时间戳均来自于主节点的 Event；
  • GTID/XID Event 的 timestamp 为主节点最后一个修改操作开始时间；
  • GTID Event 的 original_commit_timestamp 来自于主节点，immediate_commit_timestamp 为最新的时间戳；
  • exec_time = A - B
    • A = 从节点 生成 BEGIN Event 的最新时间戳
    • B = 主节点 执行第一个 DML 操作的开始时间

结语

至此，关于 binlog 中的时间戳与 exec_time 已基本梳理完成，有兴趣的朋友可以回到文章开头，再看看 Q1-Q3 是否有了答案。

最后，建议读者朋友实际模拟几个案例，以便于更加深刻的理解相关字段，后续在利用 binlog 分析主从同步问题时，能更加得心应手。

以上信息仅供交流，作者水平有限，如有不足之处，欢迎在评论区交流。

更多技术文章，请访问：https://opensource.actionsky.com/

关于 SQLE

SQLE 是一款全方位的 SQL 质量管理平台，覆盖开发至生产环境的 SQL 审核和管理。支持主流的开源、商业、国产数据库，为开发和运维提供流程自动化能力，提升上线效率，提高数据质量。

SQLE 获取

类型 地址
版本库 https://github.com/actiontech/sqle
文档 https://actiontech.github.io/sqle-docs/
发布信息 https://github.com/actiontech/sqle/releases
数据审核插件开发文档 https://actiontech.github.io/sqle-docs/docs/dev-manual/plugins/howtouse
原文链接：https://my.oschina.net/actiontechoss/blog/11112538
关注公众号

低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。

持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。

转载内容版权归作者及来源网站所有，本站原创内容转载请注明来源。

相关文章

    文章评论

    共有0条评论来说两句吧...

    文章二维码

    扫描即可查看该文章

    点击排行

    推荐阅读

    最新文章