MySQL Bugs: #50954: start_time in slow query log is recording the query end time, not start time

Bug #50954	start_time in slow query log is recording the query end time, not start time
Submitted:	5 Feb 2010 19:46	Modified:	6 Feb 2010 10:19
Reporter:	eric t	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	MySQL 5.1.32, 5.1, 5.5.99	OS:	Linux (Red Hat 4.1.2-44)
Assigned to:		CPU Architecture:	Any
Tags:	slow query log

Description:
When a query saved in the slow query log, the start_time value is the query finish time or record logged time, not the real query start time. This is found when we ran a query for 4 hours long and in the logs the start_time is current time, not the time 4 hours ago.

How to repeat:
Run a query longer then log_query_time and check the start_time.

Suggested fix:
If this is true, it is better to change the start_time to end_time to resolve the confusion of the definition.

Thank you for the report.

I see in slow query log following:

Time                 Id Command    Argument
# Time: 100206 11:43:14
# User@Host: root[root] @ localhost []
# Query_time: 100.002342  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use test;
SET timestamp=1265445794;
select sleep(100);

Where did you see start_time?

Hi,

I choose to save the log to the table in mysql DB. The first column name is that start_time.

Thank you for the feedback.

Verified as described.

Test case:

select now();
select sleep(100);
select now();

select * from mysql.slow_log;

Option file:

--log-slow-queries --log-output=table

Fortunately, this is not too hard to fix. I have a test and a patch to fix this issue in 5.1.44.

First, the patch to fix the issue:

diff --git a/sql/log.cc b/sql/log.cc
index 69f8fd0..167899e 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2361,12 +2361,12 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
     }

     /*
-      This info used to show up randomly, depending on whether the query
-      checked the query start time or not. now we always write current
-      timestamp to the slow log
+      The timestamp used to only be set when the query had checked the
+      start time. Now the slow log always logs the query start time.
+      This ensures logs can be used to replicate queries accurately.
     */
     end= strmov(end, ",timestamp=");
-    end= int10_to_str((long) current_time, end, 10);
+    end= int10_to_str((long) query_start_arg, end, 10);

     if (end != buff)
     {

A fast test to catch the problem and verify the fix (sleep 2 is much faster than sleep 100!):

diff --git a/mysql-test/t/slow_log-master.opt b/mysql-test/t/slow_log-master.opt
new file mode 100644
index 0000000..445da5d
--- /dev/null
+++ b/mysql-test/t/slow_log-master.opt
@@ -0,0 +1 @@
+--slow-query-log=1 --long-query-time=1
diff --git a/mysql-test/t/slow_log.test b/mysql-test/t/slow_log.test
new file mode 100644
index 0000000..d9b4250
--- /dev/null
+++ b/mysql-test/t/slow_log.test
@@ -0,0 +1,7 @@
+select @@datadir;
+set timestamp=10;
+select unix_timestamp(), sleep(2);
+
+--exec [ "1" == `grep "SET timestamp=10;" $MYSQL_TEST_DIR/var/mysqld.1/mysqld-slow.log | wc -l` ]
+
+--exit

My fix is only for the slow log file, but a similar fix for the table should be similarly straightforward.