Understanding Timestamp and exec_time in MySQL Binlog Events

MySQL binlog entries contain a time attribute that appears in the form #161213 10:11:35 . The article first shows a typical binlog snippet and raises questions about why events from different transactions may have identical timestamps or appear out of commit order.

Through a real‑world Galera Cluster case, three transactions are examined; the second transaction shows all its events stamped at 10:11:30 even though it commits at 10:11:35 . The discrepancy leads to an investigation of where the timestamp originates.

The source code of Log_event::Log_event reveals that the event header’s when field is set to thd->start_time , which is initialized by thd->set_time() before each SQL statement is executed. Consequently, all events generated by a single statement inherit the same timestamp.

Further code shows how exec_time is computed: the difference between the current time at statement completion and thd->start_time . This explains why a transaction that runs a single statement for five seconds shows exec_time=5 while its events retain the start‑time timestamp.

Because autocommit transactions consist of a single statement, thd->set_time() is called only once, so every event in that transaction shows the same timestamp. An experiment with SET autocommit=0 , an INSERT followed by SLEEP(5) , and an explicit COMMIT demonstrates that the commit‑related events (GTID and Xid) receive a later timestamp, matching the time when COMMIT is executed.

The article also discusses the ordering of events within a transaction. GTID and Xid events are generated at commit time and are placed at the beginning of the transaction’s binlog segment, which explains why their timestamps may be later than those of the data‑modifying events that appear later in the log.

Overall, the piece clarifies the relationship between binlog timestamps, exec_time, and transaction boundaries, providing both conceptual explanations and concrete code excerpts.