Buy Percona ServicesBuy Now!

What is exec_time in binary logs?

 | January 31, 2011 |  Posted In: Insight for DBAs, MySQL


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.

Baron Schwartz

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


Leave a Reply