Solving incorrect exec_time stats for queries in MySQL’s binary log

Due to MySQL Bug #52704, if your server’s clock happens to tick backwards during a query’s execution, the Exec_time listed in the binary log will become a huge number like 4294967295 (which is -1 casted to a 32-bit unsigned quantity):

#140427 13:48:52 server id 1  end_log_pos 23475         Query   thread_id=7782750       exec_time=4294967295    error_code=0
SET TIMESTAMP=1398606532/*!*/;
INSERT INTO phpbb_privmsgs_to  (msg_id, user_id, author_id, folder_id, pm_new, pm_unread, pm_forwarded) VALUES (53165565, 65, 2, -3, 1, 1, 0)
/*!*/;
# at 23475

The clock ticking backwards is likely to be caused by your server’s time being adjusted by NTP.

Since it causes those queries to have stupidly large execution times, when you’re trying to examine the binary log with pt-query-digest, it completely throws off all the statistics and makes the tool unusable.

You can solve this issue by adding a custom “filter” to your pt-query-digest call which sets the exec_time of the query to zero if it looks too large to be real:

mysqlbinlog mysql-bin.000526 | pt-query-digest --type binlog --filter '(($event->{Query_time} || 0) > 2147483648 ? $event->{Query_time} = 0 : 1) || 1'

Leave a Reply

Your email address will not be published. Required fields are marked *