MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:tim Date:April 4 2007 7:40pm
Subject:bk commit into 5.1 tree (tsmith:1.2559) BUG#27638
View as plain text  
Below is the list of changes that have just been committed into a local
5.1 repository of tsmith. When tsmith does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html

ChangeSet@stripped, 2007-04-04 21:40:47+02:00, tsmith@stripped +6 -0
  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.

  include/my_time.h@stripped, 2007-04-04 21:36:08+02:00, tsmith@stripped +2 -0
    Add TIME_MAX_VALUE_SECONDS definition

  mysql-test/r/log_tables-big.result@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +29 -0
    BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/r/log_tables-big.result

  mysql-test/r/log_tables-big.result@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +0 -0

  mysql-test/t/log_tables-big-master.opt@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +1 -0
    BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/t/log_tables-big-master.opt

  mysql-test/t/log_tables-big-master.opt@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +0 -0

  mysql-test/t/log_tables-big.test@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +35 -0
    BitKeeper file /benchmarks/ext3/TOSAVE/tsmith/bk/maint/51/mysql-test/t/log_tables-big.test

  mysql-test/t/log_tables-big.test@stripped, 2007-04-04 21:33:02+02:00, tsmith@stripped +0 -0

  sql/log.cc@stripped, 2007-04-04 21:35:52+02:00, tsmith@stripped +12 -2
    Log_to_csv_event_handler::log_slow(): call store_time() instead of store() for query_time and lock_time

  sql/time.cc@stripped, 2007-04-04 21:34:02+02:00, tsmith@stripped +5 -0
    initialize all TIME fields (except neg, which may store a
    needed value) in calc_time_from_sec()

# This is a BitKeeper patch.  What follows are the unified diffs for the
# set of deltas contained in the patch.  The rest of the patch, the part
# that BitKeeper cares about, is below these diffs.
# User:	tsmith
# Host:	quadxeon.mysql.com
# Root:	/benchmarks/ext3/TOSAVE/tsmith/bk/maint/51

--- 1.274/sql/log.cc	2007-04-02 10:54:27 +02:00
+++ 1.275/sql/log.cc	2007-04-04 21:35:52 +02:00
@@ -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))

--- 1.76/sql/time.cc	2006-12-31 01:06:37 +01:00
+++ 1.77/sql/time.cc	2007-04-04 21:34:02 +02:00
@@ -313,6 +313,11 @@ void localtime_to_TIME(TIME *to, struct 
 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;

--- 1.30/include/my_time.h	2007-03-07 10:24:04 +01:00
+++ 1.31/include/my_time.h	2007-04-04 21:36:08 +02:00
@@ -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);
--- New file ---
+++ mysql-test/r/log_tables-big.result	07/04/04 21:33:02
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

--- New file ---
+++ mysql-test/t/log_tables-big-master.opt	07/04/04 21:33:02
--log-slow-queries

--- New file ---
+++ mysql-test/t/log_tables-big.test	07/04/04 21:33:02
# 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;

Thread
bk commit into 5.1 tree (tsmith:1.2559) BUG#27638tim4 Apr