Understanding exec_time in MySQL Binlog and Its Impact on Replication Lag

Background

While troubleshooting a customer's MySQL master‑slave delay, an unusual behavior related to exec_time in the binlog was observed. The author conducted a series of experiments to clarify its semantics.

What is exec_time

exec_time

is the value recorded in the binary log that represents the elapsed time of a transaction or statement, measured in seconds. The article explores whether it reflects a single statement, an entire transaction, or something else.

Environment Preparation

Two MySQL 5.7.32 servers were set up (master at 10.186.60.62, slave at 10.186.60.68) with a simple test table t:

[email protected] [zlm]> show create table t\G
*************************** 1. row ***************************
        Table: t
Create Table: CREATE TABLE `t` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

[email protected] [zlm]> select * from t;
Empty set (0.01 sec)

Test 1 – binlog_format=row

A transaction with two INSERT statements (one sleeping 5 s, the other 10 s) was executed.

[email protected] [zlm]> select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| ROW |
+-----------------+
1 row in set (0.00 sec)

[email protected] [zlm]> begin;insert into t values(sleep(5));insert into t values(sleep(10));commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected (5.04 sec)
Query OK, 1 row affected (10.00 sec)
Query OK, 0 rows affected (0.00 sec)

Observations:

Master binlog recorded exec_time ≈ 6 s (close to the first INSERT).

Slave binlog recorded exec_time ≈ 16 s, matching the whole transaction duration.

A second variant added two SELECT SLEEP() statements, causing the slave exec_time to miss the time of the failed SELECT, confirming that exec_time on the slave approximates the transaction execution time on the master.

Conclusion 1

In row mode, a transaction records exec_time only once.

Master exec_time ≈ execution time of the first statement.

Slave exec_time ≈ total transaction execution time.

Note 1

Enable binlog_rows_query_log_events=1 on the master to log full SQL in the binlog, which aids fault analysis.

Test 2 – binlog_format=statement

- set @@session.binlog_format=statement;
Query OK, 0 rows affected (0.00 sec)

[email protected] [zlm]> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| STATEMENT |
+-------------------------+
1 row in set (0.00 sec)

[email protected] [zlm]> begin;insert into t values(sleep(10));insert into t values(sleep(5));commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected, 1 warning (10.01 sec)
Query OK, 1 row affected, 1 warning (5.01 sec)
Query OK, 0 rows affected (0.00 sec)

Observations:

Master recorded three exec_time entries (10 s, 10 s, 5 s).

Slave (still in row mode) recorded a single exec_time ≈ 25 s, larger than the actual transaction time, indicating double‑counting of the BEGIN time.

Conclusion 2

In statement mode, each DML statement gets its own exec_time (SELECTs are excluded).

Master exec_time still mirrors the first statement’s duration.

Slave exec_time approximates the whole transaction duration.

Note 2

Using READ COMMITTED isolation level with statement binlog is prohibited; it will cause errors.

Principle Analysis

exec_time

equals the difference between the transaction start timestamp and end timestamp (Unix time) in seconds.

After commit, the master writes the end timestamp to the binlog; the slave receives the same start timestamp but records its own end timestamp after replay, so slave exec_time is always ≥ actual execution time.

Fault Case

A real incident showed master‑slave delay > 1000 s. Examining binlogs revealed a linearly increasing exec_time on the slave, correlating with Seconds_Behind_Master.

Fault Simulation

Test 1 – Disk I/O Bottleneck

Using stress to saturate disk I/O while the slave runs parallel replication (LOGICAL_CLOCK, 8 workers). Disk usage hit 100 % and await > 350 ms, causing the slave to fall behind by up to 8 s.

Test 2 – CPU Bottleneck

Running stress --cpu 4 raised CPU usage > 90 % and load ≈ 11, leading the slave to lag up to 17 s, with matching exec_time values in the binlog.

Test 3 – Network Latency

Applying tc to add 500 ms latency on the slave’s NIC caused delay to exceed 7 minutes; filtering slave binlog for exec_time=427 matched the observed Seconds_Behind_Master. Removing the latency restored normal replication.

Summary

Slave binlog exec_time can indicate transaction execution speed but does not always equal master execution time.

When master exec_time stays 0 while slave exec_time rises, it likely signals replication lag caused by CPU, disk, or network bottlenecks.

These observations assume timestamps are not manually altered.

References

https://www.percona.com/blog/2011/01/31/what-is-exec_time-in-binary-logs/

https://mp.weixin.qq.com/s/TAf4yCC1g_xrvEq2BHJINQ