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

2024-05-14 290

详解 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业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。

Linux 基金会成立高性能软件基金会（HPSF）

Linux 基金会宣布成立高性能软件基金会（High Performance Software Foundation，简称 HPSF）。HPSF 旨在通过一系列技术项目，通过增加采用、降低贡献门槛和支持开发工作，构建、推广和推进用于高性能计算（HPC）的可移植核心软件堆栈。公告称，HPSF 将为高性能计算生态系统中的关键项目提供一个中立的空间，使工业界、学术界和政府机构能够在科学软件堆栈方面开展合作。以及通过一系列重点举措让高性能软件开发人员的生活变得更轻松，包括：为 HPC 项目量身定制的持续集成资源、持续构建的即插即用软件堆栈、架构支持、性能回归测试和基准测试、与其他 Linux 基金会项目（如 OpenSSF、UEC、UXL 基金会和 CNCF）的合作。 HPSF 启动了以下初始开源技术项目： Spack：HPC 包管理器。 Kokkos：一种可在硬件无关方式下编写现代 C++应用程序的性能可移植编程模型。 Viskores（之前称为 VTK-m）：用于加速器架构的科学可视化算法工具包。 HPCToolkit：适用于从台式系统到 GPU 加速超级计算机的性能测量和分析工具。 A...

2024-05-14

288

5月14日，腾讯宣布旗下的混元文生图大模型全面升级并对外开源，目前已在 Hugging Face 平台及 Github 上发布，包含模型权重、推理代码、模型算法等完整模型，可供企业与个人开发者免费商用。这是业内首个中文原生的 DiT 架构文生图开源模型，支持中英文双语输入及理解，参数量15亿。升级后的混元文生图大模型采用了与 sora 一致的 DiT 架构，不仅可支持文生图，也可作为视频等多模态视觉生成的基础。评测数据显示，最新的腾讯混元文生图模型效果远超开源的 Stable Diffusion 模型，是目前效果最好的开源文生图模型；整体能力属于国际领先水平。自研新一代文生图模型大模型的优异表现，离不开领先的技术架构。升级后的腾讯混元文生图大模型采用了全新的 DiT 架构（DiT，即Diffusion With Transformer），这也是 Sora 和 Stable Diffusion 3 的同款架构和关键技术，是一种基于 Transformer 架构的扩散模型。过去，视觉生成扩散模型主要基于 U-Net 架构，但随着参数量的提升，基于 Transformer 架构的...

2024-05-14

507

资源下载

更多资源

优质分享App

近一个月的开发和优化，本站点的第一个app全新上线。该app采用极致压缩，本体才4.36MB。系统里面做了大量数据访问、缓存优化。方便用户在手机上查看文章。后续会推出HarmonyOS的适配版本。

Nacos

Nacos /nɑ:kəʊs/ 是 Dynamic Naming and Configuration Service 的首字母简称，一个易于构建 AI Agent 应用的动态服务发现、配置管理和AI智能体管理平台。Nacos 致力于帮助您发现、配置和管理微服务及AI智能体应用。Nacos 提供了一组简单易用的特性集，帮助您快速实现动态服务发现、服务配置、服务元数据、流量管理。Nacos 帮助您更敏捷和容易地构建、交付和管理微服务平台。

Spring

Spring框架（Spring Framework）是由Rod Johnson于2002年提出的开源Java企业级应用框架，旨在通过使用JavaBean替代传统EJB实现方式降低企业级编程开发的复杂性。该框架基于简单性、可测试性和松耦合性设计理念，提供核心容器、应用上下文、数据访问集成等模块，支持整合Hibernate、Struts等第三方框架，其适用范围不仅限于服务器端开发，绝大多数Java应用均可从中受益。

Rocky Linux

Rocky Linux（中文名：洛基）是由Gregory Kurtzer于2020年12月发起的企业级Linux发行版，作为CentOS稳定版停止维护后与RHEL（Red Hat Enterprise Linux）完全兼容的开源替代方案，由社区拥有并管理，支持x86_64、aarch64等架构。其通过重新编译RHEL源代码提供长期稳定性，采用模块化包装和SELinux安全架构，默认包含GNOME桌面环境及XFS文件系统，支持十年生命周期更新。

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

概述

主节点 binlog 日志

1. GTID Event

timestamp

immediate_commit_timestamp/original_commit_timestamp

2. BEGIN Event

timestamp

exec_time

3. Table_map Event

4. Write Event

5. Xid Event

6. 主节点小结

从节点 binlog 日志

1. GTID Event

timestamp

immediate_commit_timestamp/original_commit_timestamp

公式

2. BEGIN Event

timestamp

exec_time

公式

3. Table_map Event

4. Write Event

5. Xid Event

6. 从节点小节

结语

关于 SQLE

SQLE 获取

Linux 基金会成立高性能软件基金会（HPSF）

腾讯宣布混元文生图大模型开源： Sora 同架构，可免费商用

相关文章

发表评论

资源下载

优质分享App

Nacos

Spring

Rocky Linux

欢迎您！