November 1, 2014

What is exec_time in binary logs?

If you’ve used MySQL’s mysqlbinlog tool, you’ve probably seen something like the following in the output: “exec_time=0″ What is the exec_time? It seems to be the query’s execution time, but it is not.

In most cases, the exec_time will be similar to the query execution time on the server where the query originally ran. If you’re running replication, then on the replication master, the exec_time will look believable. But on replicas, exec_time can be completely different. Suppose you execute an UPDATE that takes one second to run on the master. This gets logged into the binary log and copied to replicas for replay. Now suppose that you have also set log_slave_updates on the replica. When the statement executes in the replication thread, it will be logged to the replica’s binary log so it can be replicated to other servers in turn.

If you use mysqlbinlog to examine the replica’s binary log, you might see a very different exec_time, such as exec_time=1000, even if the statement did not take 1000 seconds to execute. Why is that?

The reason is that the exec_time is the difference from the statement’s original start timestamp and the time at which it completed executing. On the originating server, that’s accurate to within the tolerance of a one-second timestamp. However, replicas might execute the statement much later. And in those cases, the end timestamp will be much later than the start timestamp on the originating server, thus causing the statement to appear to have taken a long time to execute.

About Baron Schwartz

Baron is the lead author of High Performance MySQL.
He is a former Percona employee.

Comments

  1. David says:

    So does this mean the value on the replica might give you a rough idea how far behind the slave was at the time?

  2. Yes, good point! I had not thought of using it for that purpose. As long as you know the response time of the query, you know how much time elapsed between the master and replica executing it.

Speak Your Mind

*