Understanding Timestamp and exec_time Fields in MySQL Binlog (Master and Slave)

1 Overview

During a recent test a system showed replication lag; inspecting the binlog with mysqlbinlog revealed confusing timestamp information. The article presents a binlog excerpt and raises questions about the meaning and calculation of fields such as original_commit_timestamp , immediate_commit_timestamp , and their relationship to the timestamp shown in events.

Key questions include:

What do the fields in P2 represent and how are they computed?

How do the P2 fields relate to the timestamp observed in P1?

How is the timestamp in P1 obtained, especially in a master‑slave environment?

The article proceeds to verify these questions through testing and source‑code analysis.

2 Master Binlog Logs

1. GTID Event

timestamp

On the master, the timestamp of an event is captured at the start of dispatch_command() via thd->start_time and stored in Log_event::common_header->when when the event object is created.

Relevant call stack:

#|-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)
      // set 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(...)
            ...
            |-Rows_log_event *const ev = new RowsEventT(...)
            ...
            |-Xid_log_event end_evt(thd, xid)

immediate_commit_timestamp / original_commit_timestamp

The immediate_commit_timestamp records the commit moment, while original_commit_timestamp equals immediate_commit_timestamp on the master.

#|-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) {
      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

For the master, the timestamp in a BEGIN event is not the moment the BEGIN statement is issued; it is the start time of the first DML operation that follows, taken from thd->start_time when the Table_map event is generated.

exec_time

The master’s exec_time for the BEGIN event equals the difference between the timestamp captured when the first DML finishes (A) and the start time of that DML (B): exec_time = A - B .

Stack illustration:

3. Table_map Event

4. Write Event

5. Xid Event

6 Master Summary

Except for the BEGIN event, the timestamp of each event is the start time of the corresponding SQL statement.

The timestamp in the BEGIN event reflects the start time of the first DML operation.

immediate_commit_timestamp and original_commit_timestamp represent the commit moment.

exec_time = A - B where A is the time after the first DML finishes and B is its start time.

3 Slave Binlog Logs

1. GTID Event

timestamp

On the slave, GTID events inherit the timestamp of the previous operation in the transaction because the slave does not generate its own timestamp for GTID/XID events; they use the master’s last modification timestamp.

immediate_commit_timestamp / original_commit_timestamp

The slave’s immediate_commit_timestamp records the commit moment on the slave, while original_commit_timestamp is taken from the master’s GTID event and corresponds to the master’s timestamp .

Relevant call stack:

#|-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)
                            // generate and write GTID event
                            |-ulonglong immediate_commit_timestamp = my_micro_time()
                            |-if (original_commit_timestamp == UNDEFINED_COMMIT_TIMESTAMP) {...}
                            |-Gtid_log_event gtid_event(..., original_commit_timestamp, immediate_commit_timestamp, ...)

Formula

immediate_commit_timestamp - original_commit_timestamp = A + B + C

A = time for the master to transfer the binlog to the slave

B = time for the slave to replay the binlog

C = time lost due to synchronization delay or interruption

2. BEGIN Event

timestamp

The slave’s BEGIN event timestamp is copied from the master’s BEGIN event timestamp, which ultimately comes from the master’s thd->start_time of the first DML.

exec_time

On the slave, exec_time is still calculated as the difference between the latest timestamp captured while generating the BEGIN event and the original timestamp (which originates from the master’s first DML start time).

Stack illustration:

#|-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)
          // set user_time=start_time=ev.common_header->when
          |-thd->set_time(&(common_header->when))
          |-thd->set_query(query_arg, q_len_arg)

Formula

exec_time = A + B + C + D

A = total time of the transaction on the master

B = binlog transmission time

C = synchronization delay/interrupt time

D = time for the slave to complete the first row modification

3. Table_map Event

4. Write Event

5. Xid Event

6 Slave Summary

Except for GTID/XID events, all other event timestamps on the slave come from the master.

GTID/XID event timestamp on the slave equals the master’s last modification event timestamp.

GTID event original_commit_timestamp and immediate_commit_timestamp on the slave are derived from the master’s timestamps.

exec_time = A - B where A is the slave’s latest BEGIN timestamp and B is the master’s first DML start time.

4 Conclusion

At this point the relationship between binlog timestamps and exec_time has been clarified; readers can revisit the earlier questions to verify their answers.

It is recommended to simulate a few cases to deepen understanding, which will make future binlog‑based troubleshooting of master‑slave synchronization issues more straightforward.

The information provided is for exchange only; the author’s expertise is limited, and feedback is welcome.