List:Commits« Previous MessageNext Message »
From:He Zhenxing Date:July 11 2010 12:04pm
Subject:bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453) Bug#52704
View as plain text  
#At file:///media/sdb2/hezx/work/mysql/bzr/b52704/5.1-bugteam/ based on revid:svoj@stripped

 3453 He Zhenxing	2010-07-11
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private

    added:
      mysql-test/suite/binlog/r/binlog_time.result
      mysql-test/suite/binlog/t/binlog_time-master.opt
      mysql-test/suite/binlog/t/binlog_time.test
    modified:
      sql/field.cc
      sql/item_timefunc.cc
      sql/log.cc
      sql/log_event.cc
      sql/log_event.h
      sql/set_var.cc
      sql/sql_class.cc
      sql/sql_class.h
      sql/sql_insert.cc
      sql/sql_parse.cc
      sql/sql_show.cc
=== added file 'mysql-test/suite/binlog/r/binlog_time.result'
--- a/mysql-test/suite/binlog/r/binlog_time.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/binlog/r/binlog_time.result	2010-07-11 12:04:32 +0000
@@ -0,0 +1,37 @@
+CREATE TABLE t1 (a INT);
+FLUSH LOGS;
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT INTO t1 VALUES (1);
+SET @@long_query_time= 2;
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT INTO t1 SELECT a FROM (SELECT 2 AS a, SLEEP(2)) AS t;
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP - 100;
+INSERT INTO t1 SELECT a FROM (SELECT 3 AS a, SLEEP(2)) AS t;
+SELECT 3;
+3
+3
+SET GLOBAL EVENT_SCHEDULER= ON;
+SET @@TIMESTAMP= DEFAULT;
+CREATE EVENT ev1 ON SCHEDULE AT CURRENT_TIMESTAMP
+DO BEGIN
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT INTO t1 VALUES (4);
+END;|
+CREATE EVENT ev2 ON SCHEDULE AT CURRENT_TIMESTAMP
+DO BEGIN
+SET @@long_query_time= 2;
+SET @@TIMESTAMP= @@TIMESTAMP - 100;
+INSERT INTO t1 SELECT a FROM (SELECT 5 AS a, SLEEP(2)) AS t;
+END;|
+SET GLOBAL EVENT_SCHEDULER= OFF;
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT DELAYED INTO t1 VALUES (6),(7),(8);
+INSERT DELAYED INTO t1 SELECT a FROM (SELECT 9 AS a, SLEEP(2)) AS t;
+FLUSH TABLES;
+FLUSH LOGS;
+SLOW_LOG_COUNT
+4
+DROP TABLE t1;

=== added file 'mysql-test/suite/binlog/t/binlog_time-master.opt'
--- a/mysql-test/suite/binlog/t/binlog_time-master.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/binlog/t/binlog_time-master.opt	2010-07-11 12:04:32 +0000
@@ -0,0 +1 @@
+--log-output=table,file
\ No newline at end of file

=== added file 'mysql-test/suite/binlog/t/binlog_time.test'
--- a/mysql-test/suite/binlog/t/binlog_time.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/binlog/t/binlog_time.test	2010-07-11 12:04:32 +0000
@@ -0,0 +1,105 @@
+#
+# binlog_time.test
+#
+# Bug#52704
+#
+# Before fixing bug#52704, the start time was affected by the session
+# variable @@TIMESTAMP, while the end time is always the system time,
+# which means the start time would be larger than the end time if
+# TIMESTAMP was set to a future time before starting the query, and
+# the exec time (ulong (end_time - start_time)) of this query would
+# result in a very large value.
+#
+source include/have_log_bin.inc;
+
+let $MYSQLD_DATADIR= `select @@datadir`;
+
+CREATE TABLE t1 (a INT);
+
+FLUSH LOGS;
+
+# Let's assume that the simple INSERT won't take longer than 100s to
+# finish :). 
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT INTO t1 VALUES (1);
+
+# Set long_query_time to a short time (default 10s) to make the test
+# run faster.
+SET @@long_query_time= 2;
+
+# Save the original slow log count
+let $save_slow_log_count= `select count(*) from mysql.slow_log`;
+
+# Both of the following two statements should appear in slow log
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+disable_warnings;
+INSERT INTO t1 SELECT a FROM (SELECT 2 AS a, SLEEP(2)) AS t;
+enable_warnings;
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP - 100;
+disable_warnings;
+INSERT INTO t1 SELECT a FROM (SELECT 3 AS a, SLEEP(2)) AS t;
+enable_warnings;
+
+# save the number of rows already in t1, this value is used to wait
+# for the follow events to complete.
+let $count = `SELECT COUNT(*) FROM t1`;
+eval SELECT $count;
+
+SET GLOBAL EVENT_SCHEDULER= ON;
+SET @@TIMESTAMP= DEFAULT;
+DELIMITER |;
+CREATE EVENT ev1 ON SCHEDULE AT CURRENT_TIMESTAMP
+DO BEGIN
+	SET @@TIMESTAMP= @@TIMESTAMP + 100;
+	INSERT INTO t1 VALUES (4);
+END;|
+
+CREATE EVENT ev2 ON SCHEDULE AT CURRENT_TIMESTAMP
+DO BEGIN
+	SET @@long_query_time= 2;
+	SET @@TIMESTAMP= @@TIMESTAMP - 100;
+	INSERT INTO t1 SELECT a FROM (SELECT 5 AS a, SLEEP(2)) AS t;
+END;|
+DELIMITER ;|
+
+# Wait for the above events to complete, which will add two more rows.
+let $count= $count + 2;
+let $table= t1;
+source include/wait_until_rows_count.inc;
+SET GLOBAL EVENT_SCHEDULER= OFF;
+
+# Insert delayed
+SET @@TIMESTAMP= DEFAULT;
+SET @@TIMESTAMP= @@TIMESTAMP + 100;
+INSERT DELAYED INTO t1 VALUES (6),(7),(8);
+disable_warnings;
+INSERT DELAYED INTO t1 SELECT a FROM (SELECT 9 AS a, SLEEP(2)) AS t;
+enable_warnings;
+FLUSH TABLES;
+
+# Verify that the slow queries are not fooled by changing TIMESTAMP.
+FLUSH LOGS;
+disable_query_log;
+eval SELECT COUNT(*) - $save_slow_log_count AS SLOW_LOG_COUNT FROM mysql.slow_log;
+enable_query_log;
+
+# Search in the dump of binary log for exec_time that are very large.
+perl;
+use strict;
+use warnings;
+open(FILE, "$ENV{'MYSQL_BINLOG'} $ENV{'MYSQLTEST_VARDIR'}/mysqld.1/data/master-bin.000002 |") or die;
+my $line;
+while ($line = <FILE>)
+{
+    if ($line =~ /.*exec_time=([0-9]*).*/)
+    {
+        print "Found incorrect exec_time: $1\n" if $1 > 100;
+    }
+}
+close(FILE);
+EOF
+
+# Cleanup
+DROP TABLE t1;

=== modified file 'sql/field.cc'
--- a/sql/field.cc	2010-03-17 18:15:41 +0000
+++ b/sql/field.cc	2010-07-11 12:04:32 +0000
@@ -5121,7 +5121,7 @@ void Field_timestamp::sql_type(String &r
 void Field_timestamp::set_time()
 {
   THD *thd= table ? table->in_use : current_thd;
-  long tmp= (long) thd->query_start();
+  long tmp= (long) thd->query_user_start();
   set_notnull();
   store_timestamp(tmp);
 }

=== modified file 'sql/item_timefunc.cc'
--- a/sql/item_timefunc.cc	2010-02-26 13:16:46 +0000
+++ b/sql/item_timefunc.cc	2010-07-11 12:04:32 +0000
@@ -1300,7 +1300,7 @@ longlong Item_func_unix_timestamp::val_i
   
   DBUG_ASSERT(fixed == 1);
   if (arg_count == 0)
-    return (longlong) current_thd->query_start();
+    return (longlong) current_thd->query_user_start();
   if (args[0]->type() == FIELD_ITEM)
   {						// Optimize timestamp field
     Field *field=((Item_field*) args[0])->field;
@@ -1564,7 +1564,7 @@ void Item_func_curdate_local::store_now_
 {
   THD *thd= current_thd;
   thd->variables.time_zone->gmt_sec_to_TIME(now_time, 
-                                             (my_time_t)thd->query_start());
+                                             (my_time_t)thd->query_user_start());
   thd->time_zone_used= 1;
 }
 
@@ -1576,7 +1576,7 @@ void Item_func_curdate_local::store_now_
 void Item_func_curdate_utc::store_now_in_TIME(MYSQL_TIME *now_time)
 {
   my_tz_UTC->gmt_sec_to_TIME(now_time, 
-                             (my_time_t)(current_thd->query_start()));
+                             (my_time_t)(current_thd->query_user_start()));
   /* 
     We are not flagging this query as using time zone, since it uses fixed
     UTC-SYSTEM time-zone.
@@ -1621,7 +1621,7 @@ void Item_func_curtime_local::store_now_
 {
   THD *thd= current_thd;
   thd->variables.time_zone->gmt_sec_to_TIME(now_time, 
-                                             (my_time_t)thd->query_start());
+                                             (my_time_t)thd->query_user_start());
   thd->time_zone_used= 1;
 }
 
@@ -1633,7 +1633,7 @@ void Item_func_curtime_local::store_now_
 void Item_func_curtime_utc::store_now_in_TIME(MYSQL_TIME *now_time)
 {
   my_tz_UTC->gmt_sec_to_TIME(now_time, 
-                             (my_time_t)(current_thd->query_start()));
+                             (my_time_t)(current_thd->query_user_start()));
   /* 
     We are not flagging this query as using time zone, since it uses fixed
     UTC-SYSTEM time-zone.
@@ -1670,7 +1670,7 @@ void Item_func_now_local::store_now_in_T
 {
   THD *thd= current_thd;
   thd->variables.time_zone->gmt_sec_to_TIME(now_time, 
-                                             (my_time_t)thd->query_start());
+                                             (my_time_t)thd->query_user_start());
   thd->time_zone_used= 1;
 }
 
@@ -1682,7 +1682,7 @@ void Item_func_now_local::store_now_in_T
 void Item_func_now_utc::store_now_in_TIME(MYSQL_TIME *now_time)
 {
   my_tz_UTC->gmt_sec_to_TIME(now_time, 
-                             (my_time_t)(current_thd->query_start()));
+                             (my_time_t)(current_thd->query_user_start()));
   /* 
     We are not flagging this query as using time zone, since it uses fixed
     UTC-SYSTEM time-zone.

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-03-28 11:57:33 +0000
+++ b/sql/log.cc	2010-07-11 12:04:32 +0000
@@ -1011,7 +1011,7 @@ bool LOGGER::slow_log_print(THD *thd, co
     }
 
     for (current_handler= slow_log_handler_list; *current_handler ;)
-      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
+      error= (*current_handler++)->log_slow(thd, current_time, thd->query_start(),
                                             user_host_buff, user_host_len,
                                             query_utime, lock_utime, is_command,
                                             query, query_length) || error;

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2010-03-28 11:57:33 +0000
+++ b/sql/log_event.cc	2010-07-11 12:04:32 +0000
@@ -663,7 +663,7 @@ Log_event::Log_event(THD* thd_arg, uint1
   :log_pos(0), temp_buf(0), exec_time(0), flags(flags_arg), thd(thd_arg)
 {
   server_id=	thd->server_id;
-  when=		thd->start_time;
+  when=		thd->query_user_start();
   cache_stmt=	using_trans;
 }
 
@@ -2394,7 +2394,8 @@ Query_log_event::Query_log_event(THD* th
   error_code= errcode;
 
   time(&end_time);
-  exec_time = (ulong) (end_time  - thd_arg->start_time);
+  DBUG_ASSERT(end_time >= thd_arg->query_start());
+  exec_time = (ulong) (end_time  - thd_arg->query_start());
   /**
     @todo this means that if we have no catalog, then it is replicated
     as an existing catalog of length zero. is that safe? /sven
@@ -4241,7 +4242,8 @@ Load_log_event::Load_log_event(THD *thd_
 {
   time_t end_time;
   time(&end_time);
-  exec_time = (ulong) (end_time  - thd_arg->start_time);
+  DBUG_ASSERT(end_time >= thd_arg->query_start());
+  exec_time = (ulong) (end_time  - thd_arg->query_start());
   /* db can never be a zero pointer in 4.0 */
   db_len = (uint32) strlen(db);
   table_name_len = (uint32) strlen(table_name);

=== modified file 'sql/log_event.h'
--- a/sql/log_event.h	2010-03-28 11:57:33 +0000
+++ b/sql/log_event.h	2010-07-11 12:04:32 +0000
@@ -1003,9 +1003,9 @@ public:
     if (when)
       return when;
     if (thd)
-      return thd->start_time;
+      return thd->query_user_start();
     if ((tmp_thd= current_thd))
-      return tmp_thd->start_time;
+      return tmp_thd->query_user_start();
     return my_time(0);
   }
 #endif

=== modified file 'sql/set_var.cc'
--- a/sql/set_var.cc	2010-03-31 13:12:37 +0000
+++ b/sql/set_var.cc	2010-07-11 12:04:32 +0000
@@ -2727,14 +2727,14 @@ bool sys_var_timestamp::update(THD *thd,
 
 void sys_var_timestamp::set_default(THD *thd, enum_var_type type)
 {
-  thd->user_time=0;
+  thd->set_user_time(0);
 }
 
 
 uchar *sys_var_timestamp::value_ptr(THD *thd, enum_var_type type,
 				   LEX_STRING *base)
 {
-  thd->sys_var_tmp.long_value= (long) thd->start_time;
+  thd->sys_var_tmp.long_value= (long) thd->query_user_start();
   return (uchar*) &thd->sys_var_tmp.long_value;
 }
 

=== modified file 'sql/sql_class.cc'
--- a/sql/sql_class.cc	2010-04-14 09:53:59 +0000
+++ b/sql/sql_class.cc	2010-07-11 12:04:32 +0000
@@ -639,7 +639,6 @@ THD::THD()
   main_security_ctx.init();
   security_ctx= &main_security_ctx;
   locked=some_tables_deleted=no_errors=password= 0;
-  query_start_used= 0;
   count_cuted_fields= CHECK_FIELD_IGNORE;
   killed= NOT_KILLED;
   col_access=0;

=== modified file 'sql/sql_class.h'
--- a/sql/sql_class.h	2010-04-14 09:53:59 +0000
+++ b/sql/sql_class.h	2010-07-11 12:04:32 +0000
@@ -1413,7 +1413,6 @@ public:
   uint32     file_id;			// for LOAD DATA INFILE
   /* remote (peer) port */
   uint16 peer_port;
-  time_t     start_time, user_time;
   // track down slow pthread_create
   ulonglong  prior_thr_create_utime, thr_create_utime;
   ulonglong  start_utime, utime_after_lock;
@@ -1466,6 +1465,7 @@ public:
   int binlog_remove_pending_rows_event(bool clear_maps);
 
 private:
+  time_t     start_time, user_time;
   /*
     Number of outstanding table maps, i.e., table maps in the
     transaction cache.
@@ -1824,7 +1824,7 @@ public:
     Reset to FALSE when we leave the sub-statement mode.
   */
   bool       is_fatal_sub_stmt_error;
-  bool	     query_start_used, rand_used, time_zone_used;
+  bool	     rand_used, time_zone_used;
   /* for IS NULL => = last_insert_id() fix in remove_eq_conds() */
   bool       substitute_null_with_insert_id;
   bool	     in_lock_tables;
@@ -2005,22 +2005,22 @@ public:
     proc_info = old_msg;
     pthread_mutex_unlock(&mysys_var->mutex);
   }
-  inline time_t query_start() { query_start_used=1; return start_time; }
+  inline time_t query_start() { return start_time; }
+  inline void set_start_time(time_t t) { start_time= t; }
+  inline time_t query_user_start()
+  {
+    return user_time ? user_time : start_time;
+  }
+  inline void set_user_time(time_t t) { user_time= t; }
   inline void set_time()
   {
-    if (user_time)
-    {
-      start_time= user_time;
-      start_utime= utime_after_lock= my_micro_time();
-    }
-    else
-      start_utime= utime_after_lock= my_micro_time_and_time(&start_time);
+    start_utime= utime_after_lock= my_micro_time_and_time(&start_time);
   }
   inline void	set_current_time()    { start_time= my_time(MY_WME); }
   inline void	set_time(time_t t)
   {
-    start_time= user_time= t;
-    start_utime= utime_after_lock= my_micro_time();
+    user_time= t;
+    set_time();
   }
   void set_time_after_lock()  { utime_after_lock= my_micro_time(); }
   ulonglong current_utime()  { return my_micro_time(); }

=== modified file 'sql/sql_insert.cc'
--- a/sql/sql_insert.cc	2010-03-29 02:32:30 +0000
+++ b/sql/sql_insert.cc	2010-07-11 12:04:32 +0000
@@ -1699,7 +1699,7 @@ public:
   time_t start_time;
   ulong sql_mode;
   bool auto_increment_field_not_null;
-  bool query_start_used, ignore, log_query;
+  bool ignore, log_query;
   bool stmt_depends_on_first_successful_insert_id_in_prev_stmt;
   ulonglong first_successful_insert_id_in_prev_stmt;
   ulonglong forced_insert_id;
@@ -2187,8 +2187,7 @@ int write_delayed(THD *thd, TABLE *table
   if (!(row->record= (char*) my_malloc(table->s->reclength, MYF(MY_WME))))
     goto err;
   memcpy(row->record, table->record[0], table->s->reclength);
-  row->start_time=		thd->start_time;
-  row->query_start_used=	thd->query_start_used;
+  row->start_time=		thd->query_start();
   /*
     those are for the binlog: LAST_INSERT_ID() has been evaluated at this
     time, so record does not need it, but statement-based binlogging of the
@@ -2640,8 +2639,7 @@ bool Delayed_insert::handle_inserts(void
     pthread_mutex_unlock(&mutex);
     memcpy(table->record[0],row->record,table->s->reclength);
 
-    thd.start_time=row->start_time;
-    thd.query_start_used=row->query_start_used;
+    thd.set_start_time(row->start_time);
     /*
       To get the exact auto_inc interval to store in the binlog we must not
       use values from the previous interval (of the previous rows).

=== modified file 'sql/sql_parse.cc'
--- a/sql/sql_parse.cc	2010-03-24 16:37:41 +0000
+++ b/sql/sql_parse.cc	2010-07-11 12:04:32 +0000
@@ -1504,7 +1504,7 @@ bool dispatch_command(enum enum_server_c
     general_log_print(thd, command, NullS);
     status_var_increment(thd->status_var.com_stat[SQLCOM_SHOW_STATUS]);
     calc_sum_of_all_status(&current_global_status_var);
-    if (!(uptime= (ulong) (thd->start_time - server_start_time)))
+    if (!(uptime= (ulong) (thd->query_start() - server_start_time)))
       queries_per_second1000= 0;
     else
       queries_per_second1000= thd->query_id * LL(1000) / uptime;
@@ -5674,7 +5674,6 @@ void mysql_reset_thd_for_next_command(TH
   thd->auto_inc_intervals_in_cur_stmt_for_binlog.empty();
   thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt= 0;
 
-  thd->query_start_used= 0;
   thd->is_fatal_error= thd->time_zone_used= 0;
   /*
     Clear the status flag that are expected to be cleared at the

=== modified file 'sql/sql_show.cc'
--- a/sql/sql_show.cc	2010-03-09 10:19:10 +0000
+++ b/sql/sql_show.cc	2010-07-11 12:04:32 +0000
@@ -1859,7 +1859,7 @@ void mysqld_list_processes(THD *thd,cons
         if (mysys_var)
           pthread_mutex_unlock(&mysys_var->mutex);
 
-        thd_info->start_time= tmp->start_time;
+        thd_info->start_time= tmp->query_start();
         thd_info->query=0;
         /* Lock THD mutex that protects its data when looking at it. */
         pthread_mutex_lock(&tmp->LOCK_thd_data);
@@ -1964,8 +1964,8 @@ int fill_schema_processlist(THD* thd, TA
         table->field[4]->store(command_name[tmp->command].str,
                                command_name[tmp->command].length, cs);
       /* MYSQL_TIME */
-      table->field[5]->store((longlong)(tmp->start_time ?
-                                      now - tmp->start_time : 0), FALSE);
+      table->field[5]->store((longlong)(tmp->query_start() ?
+                                        now - tmp->query_start() : 0), FALSE);
       /* STATE */
 #ifndef EMBEDDED_LIBRARY
       val= (char*) (tmp->locked ? "Locked" :


Attachment: [text/bzr-bundle] bzr/zhenxing.he@sun.com-20100711120432-ck9lc417krhbyw5m.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453) Bug#52704He Zhenxing11 Jul
  • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453) Bug#52704Luís Soares13 Jul