Bug #27638: slow logging to CSV table inserts bad query_time and lock_time values

When MySQL logged slow query information to a CSV table, it stored the
query_time and lock_time values with an incorrect formula.

If the time was over 59 seconds, this caused incorrect statistics (either the
slow query was not logged, or the time was far from correct).  This change
fixes the method used to store those TIME values in the slow_log table.


mysql-test/r/log_tables-big.result:
  BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/r/log_tables-big.result
mysql-test/t/log_tables-big-master.opt:
  BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/t/log_tables-big-master.opt
mysql-test/t/log_tables-big.test:
  BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/t/log_tables-big.test
sql/time.cc:
  initialize all TIME fields (except neg, which may store a
  needed value) in calc_time_from_sec()
sql/log.cc:
  Log_to_csv_event_handler::log_slow(): call store_time() instead of store() for query_time and lock_time
include/my_time.h:
  Add TIME_MAX_VALUE_SECONDS definition

include/my_time.h

@@ -72,6 +72,8 @@ typedef long my_time_t;
 #define TIME_MAX_SECOND 59
 #define TIME_MAX_VALUE (TIME_MAX_HOUR*10000 + TIME_MAX_MINUTE*100 + \
                         TIME_MAX_SECOND)
+#define TIME_MAX_VALUE_SECONDS (TIME_MAX_HOUR * 3600L + \
+                                TIME_MAX_MINUTE * 60L + TIME_MAX_SECOND)
 
 my_bool check_date(const MYSQL_TIME *ltime, my_bool not_zero_date,
                    ulong flags, int *was_cut);

mysql-test/r/log_tables-big.result

+set session long_query_time=10;
+select get_lock('bug27638', 1);
+get_lock('bug27638', 1)
+1
+set session long_query_time=1;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 2);
+get_lock('bug27638', 2)
+0
+select if (query_time between '00:00:01' and '00:00:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 2)
+truncate table mysql.slow_log;
+select get_lock('bug27638', 60);
+get_lock('bug27638', 60)
+0
+select if (query_time between '00:00:59' and '00:01:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 60)
+truncate table mysql.slow_log;
+select get_lock('bug27638', 101);
+get_lock('bug27638', 101)
+0
+select if (query_time between '00:01:40' and '00:01:50', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 101)
+select release_lock('bug27638');
+release_lock('bug27638')
+1

mysql-test/t/log_tables-big-master.opt

+--log-slow-queries

mysql-test/t/log_tables-big.test

+# this test needs multithreaded mysqltest
+-- source include/not_embedded.inc
+
+# Test sleeps for long times
+--source include/big_test.inc
+
+# check that CSV engine was compiled in
+--source include/have_csv.inc
+
+connect (con1,localhost,root,,);
+connect (con2,localhost,root,,);
+
+#
+# Bug #27638: slow logging to CSV table inserts bad query_time and lock_time values
+#
+connection con1;
+set session long_query_time=10;
+select get_lock('bug27638', 1);
+connection con2;
+set session long_query_time=1;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 2);
+select if (query_time between '00:00:01' and '00:00:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 60);
+select if (query_time between '00:00:59' and '00:01:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 101);
+select if (query_time between '00:01:40' and '00:01:50', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+connection con1;
+select release_lock('bug27638');
+connection default;
+
+disconnect con1;
+disconnect con2;

sql/log.cc

@@ -569,11 +569,21 @@ bool Log_to_csv_event_handler::
 
   if (query_start_arg)
   {
+    /*
+      A TIME field can not hold the full longlong range; query_time or
+      lock_time may be truncated without warning here, if greater than
+      839 hours (~35 days)
+    */
+    TIME t;
+    t.neg= 0;
+
     /* fill in query_time field */
-    if (table->field[2]->store(query_time, TRUE))
+    calc_time_from_sec(&t, (long) min(query_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
+    if (table->field[2]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* lock_time */
-    if (table->field[3]->store(lock_time, TRUE))
+    calc_time_from_sec(&t, (long) min(lock_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
+    if (table->field[3]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* rows_sent */
     if (table->field[4]->store((longlong) thd->sent_row_count, TRUE))

sql/time.cc

@@ -313,6 +313,11 @@ void localtime_to_TIME(TIME *to, struct tm *from)
 void calc_time_from_sec(TIME *to, long seconds, long microseconds)
 {
   long t_seconds;
+  // to->neg is not cleared, it may already be set to a useful value
+  to->time_type= MYSQL_TIMESTAMP_TIME;
+  to->year= 0;
+  to->month= 0;
+  to->day= 0;
   to->hour= seconds/3600L;
   t_seconds= seconds%3600L;
   to->minute= t_seconds/60L;