MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:He Zhenxing Date:June 7 2010 12:20am
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-06-07
      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_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.

    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_event.cc
      sql/sql_class.h
=== 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-06-07 00:20:43 +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-06-07 00:20:43 +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-06-07 00:20:43 +0000
@@ -0,0 +1,110 @@
+#
+# 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 $binlog_start= query_get_value(SHOW MASTER STATUS, Position, 1);
+
+# 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;
+
+exec $MYSQL_BINLOG $MYSQLD_DATADIR/master-bin.000002 > $MYSQLTEST_VARDIR/tmp/bug52704.txt;
+
+# Search in the dump of binary log for exec_time that are very large.
+perl;
+use strict;
+use warnings;
+my $file = "$ENV{'MYSQLTEST_VARDIR'}/tmp/bug52704.txt";
+open(FILE, "<", $file) 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-06-07 00:20:43 +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-06-07 00:20:43 +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_event.cc'
--- a/sql/log_event.cc	2010-03-28 11:57:33 +0000
+++ b/sql/log_event.cc	2010-06-07 00:20:43 +0000
@@ -2394,6 +2394,7 @@ Query_log_event::Query_log_event(THD* th
   error_code= errcode;
 
   time(&end_time);
+  DBUG_ASSERT(end_time >= thd_arg->start_time);
   exec_time = (ulong) (end_time  - thd_arg->start_time);
   /**
     @todo this means that if we have no catalog, then it is replicated
@@ -4241,6 +4242,7 @@ Load_log_event::Load_log_event(THD *thd_
 {
   time_t end_time;
   time(&end_time);
+  DBUG_ASSERT(end_time >= thd_arg->start_time);
   exec_time = (ulong) (end_time  - thd_arg->start_time);
   /* db can never be a zero pointer in 4.0 */
   db_len = (uint32) strlen(db);

=== modified file 'sql/sql_class.h'
--- a/sql/sql_class.h	2010-04-14 09:53:59 +0000
+++ b/sql/sql_class.h	2010-06-07 00:20:43 +0000
@@ -2006,21 +2006,19 @@ public:
     pthread_mutex_unlock(&mysys_var->mutex);
   }
   inline time_t query_start() { query_start_used=1; return start_time; }
+  inline time_t query_user_start()
+  {
+    query_start_used=1; return user_time ? user_time : start_time;
+  }
   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(); }


Attachment: [text/bzr-bundle] bzr/zhenxing.he@sun.com-20100607002043-10yn5fhamt0z2enr.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453) Bug#52704He Zhenxing7 Jun
  • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453)Bug#52704Libing Song9 Jun
    • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3453)Bug#52704He Zhenxing10 Jun