List:Commits« Previous MessageNext Message »
From:He Zhenxing Date:October 8 2010 5:21am
Subject:bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3470) Bug#52704
View as plain text  
#At file:///media/sdb2/hezx/work/mysql/bzr/b52704/5.1-bugteam/ based on revid:li-bing.song@stripped

 3470 He Zhenxing	2010-10-08
      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.
      There are two roles mixed with thd->start_time, one is to track
      the timestamp value of the query, another is to measuring time
      intervals of query execution.
      
      This patch fixed the problem by introducing stopwatch for measuring
      time intervals of query, exec_time(for binlog), lock and after_lock.
      And thd->start_time will only be used to record the start timestamp
      of the query.
      
      The current implementation of Stopwatch is still using my_micro_time(),
      which is subject to time adjustment by user or NTP service, and
      can result in negative time interval. This is currently worked around
      by treating netagive value as 0. It should be fixed later.
     @ 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:
      mysql-test/r/information_schema.result
      mysql-test/t/information_schema.test
      sql/event_data_objects.cc
      sql/event_parse_data.cc
      sql/event_queue.cc
      sql/field.cc
      sql/item_strfunc.cc
      sql/item_timefunc.cc
      sql/log.cc
      sql/log_event.cc
      sql/log_event.h
      sql/mysqld.cc
      sql/set_var.cc
      sql/sp_head.cc
      sql/sql_acl.cc
      sql/sql_base.cc
      sql/sql_class.cc
      sql/sql_class.h
      sql/sql_insert.cc
      sql/sql_parse.cc
      sql/sql_plugin.cc
      sql/sql_show.cc
=== modified file 'mysql-test/r/information_schema.result'
--- a/mysql-test/r/information_schema.result	2010-06-25 08:01:47 +0000
+++ b/mysql-test/r/information_schema.result	2010-10-08 05:21:40 +0000
@@ -1721,9 +1721,8 @@ CREATE_OPTIONS
 KEY_BLOCK_SIZE=1
 DROP TABLE t1;
 SET TIMESTAMP=@@TIMESTAMP + 10000000;
-SELECT 'OK' AS TEST_RESULT FROM INFORMATION_SCHEMA.PROCESSLIST WHERE time < 0;
+SELECT 'NOT OK' AS TEST_RESULT FROM INFORMATION_SCHEMA.PROCESSLIST WHERE time < 0;
 TEST_RESULT
-OK
 SET TIMESTAMP=DEFAULT;
 #
 # Bug #50276: Security flaw in INFORMATION_SCHEMA.TABLES

=== 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-10-08 05:21:40 +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-10-08 05:21:40 +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-10-08 05:21:40 +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 'mysql-test/t/information_schema.test'
--- a/mysql-test/t/information_schema.test	2010-06-25 08:01:47 +0000
+++ b/mysql-test/t/information_schema.test	2010-10-08 05:21:40 +0000
@@ -1416,7 +1416,7 @@ DROP TABLE t1;
 #
 
 SET TIMESTAMP=@@TIMESTAMP + 10000000;
-SELECT 'OK' AS TEST_RESULT FROM INFORMATION_SCHEMA.PROCESSLIST WHERE time < 0;
+SELECT 'NOT OK' AS TEST_RESULT FROM INFORMATION_SCHEMA.PROCESSLIST WHERE time < 0;
 SET TIMESTAMP=DEFAULT;
 
 

=== modified file 'sql/event_data_objects.cc'
--- a/sql/event_data_objects.cc	2010-06-11 12:52:06 +0000
+++ b/sql/event_data_objects.cc	2010-10-08 05:21:40 +0000
@@ -928,7 +928,7 @@ Event_queue_element::compute_next_execut
     goto ret;
   }
 
-  time_now= (my_time_t) current_thd->query_start();
+  time_now= (my_time_t) current_thd->query_start_time();
 
   DBUG_PRINT("info",("NOW: [%lu]", (ulong) time_now));
 
@@ -1131,7 +1131,7 @@ err:
 void
 Event_queue_element::mark_last_executed(THD *thd)
 {
-  last_executed= (my_time_t) thd->query_start();
+  last_executed= (my_time_t) thd->query_start_time();
   last_executed_changed= TRUE;
 
   execution_count++;

=== modified file 'sql/event_parse_data.cc'
--- a/sql/event_parse_data.cc	2009-02-13 16:41:47 +0000
+++ b/sql/event_parse_data.cc	2010-10-08 05:21:40 +0000
@@ -111,7 +111,7 @@ Event_parse_data::init_name(THD *thd, sp
 void
 Event_parse_data::check_if_in_the_past(THD *thd, my_time_t ltime_utc)
 {
-  if (ltime_utc >= (my_time_t) thd->query_start())
+  if (ltime_utc >= (my_time_t) thd->query_start_time())
     return;
 
   /*
@@ -387,7 +387,7 @@ Event_parse_data::init_starts(THD *thd)
     goto wrong_value;
 
   DBUG_PRINT("info",("now: %ld  starts: %ld",
-                     (long) thd->query_start(), (long) ltime_utc));
+                     (long) thd->query_start_time(), (long) ltime_utc));
 
   starts_null= FALSE;
   starts= ltime_utc;

=== modified file 'sql/event_queue.cc'
--- a/sql/event_queue.cc	2008-05-09 07:43:02 +0000
+++ b/sql/event_queue.cc	2010-10-08 05:21:40 +0000
@@ -209,7 +209,7 @@ Event_queue::create_event(THD *thd, Even
 
   LOCK_QUEUE_DATA();
   *created= (queue_insert_safe(&queue, (uchar *) new_element) == FALSE);
-  dbug_dump_queue(thd->query_start());
+  dbug_dump_queue(thd->query_start_time());
   pthread_cond_broadcast(&COND_queue_state);
   UNLOCK_QUEUE_DATA();
 
@@ -261,7 +261,7 @@ Event_queue::update_event(THD *thd, LEX_
     pthread_cond_broadcast(&COND_queue_state);
   }
 
-  dbug_dump_queue(thd->query_start());
+  dbug_dump_queue(thd->query_start_time());
   UNLOCK_QUEUE_DATA();
 
   DBUG_VOID_RETURN;
@@ -287,7 +287,7 @@ Event_queue::drop_event(THD *thd, LEX_ST
 
   LOCK_QUEUE_DATA();
   find_n_remove_event(dbname, name);
-  dbug_dump_queue(thd->query_start());
+  dbug_dump_queue(thd->query_start_time());
   UNLOCK_QUEUE_DATA();
 
   /*
@@ -592,14 +592,14 @@ Event_queue::get_top_for_execution_if_ti
     thd->set_current_time(); /* Get current time */
 
     next_activation_at= top->execute_at;
-    if (next_activation_at > thd->query_start())
+    if (next_activation_at > thd->query_start_time())
     {
       /*
         Not yet time for top event, wait on condition with
         time or until signaled. Release LOCK_queue while waiting.
       */
       struct timespec top_time;
-      set_timespec(top_time, next_activation_at - thd->query_start());
+      set_timespec(top_time, next_activation_at - thd->query_start_time());
       cond_wait(thd, &top_time, queue_wait_msg, SCHED_FUNC, __LINE__);
 
       continue;
@@ -634,7 +634,7 @@ Event_queue::get_top_for_execution_if_ti
     else
       queue_replaced(&queue);
 
-    dbug_dump_queue(thd->query_start());
+    dbug_dump_queue(thd->query_start_time());
     break;
   }
 end:

=== modified file 'sql/field.cc'
--- a/sql/field.cc	2010-07-02 18:30:47 +0000
+++ b/sql/field.cc	2010-10-08 05:21:40 +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_time();
   set_notnull();
   store_timestamp(tmp);
 }

=== modified file 'sql/item_strfunc.cc'
--- a/sql/item_strfunc.cc	2010-05-03 16:14:39 +0000
+++ b/sql/item_strfunc.cc	2010-10-08 05:21:40 +0000
@@ -1690,7 +1690,7 @@ String *Item_func_encrypt::val_str(Strin
 
   if (arg_count == 1)
   {					// generate random salt
-    time_t timestamp=current_thd->query_start();
+    time_t timestamp=current_thd->query_start_time();
     salt[0] = bin_to_ascii( (ulong) timestamp & 0x3f);
     salt[1] = bin_to_ascii(( (ulong) timestamp >> 5) & 0x3f);
     salt[2] = 0;

=== modified file 'sql/item_timefunc.cc'
--- a/sql/item_timefunc.cc	2010-02-26 13:16:46 +0000
+++ b/sql/item_timefunc.cc	2010-10-08 05:21:40 +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_time();
   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_time());
   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_time()));
   /* 
     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_time());
   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_time()));
   /* 
     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_time());
   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_time()));
   /* 
     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-07-02 18:30:47 +0000
+++ b/sql/log.cc	2010-10-08 05:21:40 +0000
@@ -993,15 +993,9 @@ bool LOGGER::slow_log_print(THD *thd, co
                     user_host_buff);
 
     current_time= my_time_possible_from_micro(current_utime);
-    if (thd->start_utime)
-    {
-      query_utime= (current_utime - thd->start_utime);
-      lock_utime=  (thd->utime_after_lock - thd->start_utime);
-    }
-    else
-    {
-      query_utime= lock_utime= 0;
-    }
+    thd->stop_query_timer();
+    query_utime= thd->get_query_utime();
+    lock_utime=  thd->get_lock_utime();
 
     if (!query)
     {
@@ -1011,7 +1005,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_time(),
                                             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-07-08 02:44:26 +0000
+++ b/sql/log_event.cc	2010-10-08 05:21:40 +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_time();
   cache_stmt=	using_trans;
 }
 
@@ -2438,15 +2438,14 @@ Query_log_event::Query_log_event(THD* th
    table_map_for_update((ulonglong)thd_arg->table_map_for_update),
    master_data_written(0)
 {
-  time_t end_time;
-
   memset(&user, 0, sizeof(user));
   memset(&host, 0, sizeof(host));
 
   error_code= errcode;
 
-  time(&end_time);
-  exec_time = (ulong) (end_time  - thd_arg->start_time);
+  thd->stop_exec_timer();
+  exec_time = thd->get_exec_time();
+
   /**
     @todo this means that if we have no catalog, then it is replicated
     as an existing catalog of length zero. is that safe? /sven
@@ -4332,9 +4331,8 @@ Load_log_event::Load_log_event(THD *thd_
    table_name(table_name_arg ? table_name_arg : ""),
    db(db_arg), fname(ex->file_name), local_fname(FALSE)
 {
-  time_t end_time;
-  time(&end_time);
-  exec_time = (ulong) (end_time  - thd_arg->start_time);
+  thd->stop_exec_timer();
+  exec_time = thd->get_exec_time();
   /* 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-07-04 04:02:49 +0000
+++ b/sql/log_event.h	2010-10-08 05:21:40 +0000
@@ -1006,9 +1006,9 @@ public:
     if (when)
       return when;
     if (thd)
-      return thd->start_time;
+      return thd->query_user_time();
     if ((tmp_thd= current_thd))
-      return tmp_thd->start_time;
+      return tmp_thd->query_user_time();
     return my_time(0);
   }
 #endif

=== modified file 'sql/mysqld.cc'
--- a/sql/mysqld.cc	2010-07-02 18:30:47 +0000
+++ b/sql/mysqld.cc	2010-10-08 05:21:40 +0000
@@ -7265,7 +7265,7 @@ static int show_starttime(THD *thd, SHOW
 {
   var->type= SHOW_LONG;
   var->value= buff;
-  *((long *)buff)= (long) (thd->query_start() - server_start_time);
+  *((long *)buff)= (long) (thd->query_start_time() - server_start_time);
   return 0;
 }
 
@@ -7274,7 +7274,7 @@ static int show_flushstatustime(THD *thd
 {
   var->type= SHOW_LONG;
   var->value= buff;
-  *((long *)buff)= (long) (thd->query_start() - flush_status_time);
+  *((long *)buff)= (long) (thd->query_start_time() - flush_status_time);
   return 0;
 }
 #endif

=== modified file 'sql/set_var.cc'
--- a/sql/set_var.cc	2010-07-02 18:30:47 +0000
+++ b/sql/set_var.cc	2010-10-08 05:21:40 +0000
@@ -2731,21 +2731,21 @@ bool sys_var_timestamp::check(THD *thd, 
 
 bool sys_var_timestamp::update(THD *thd,  set_var *var)
 {
-  thd->set_time((time_t) var->save_result.ulonglong_value);
+  thd->set_user_time((time_t) var->save_result.ulonglong_value);
   return FALSE;
 }
 
 
 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_time();
   return (uchar*) &thd->sys_var_tmp.long_value;
 }
 

=== modified file 'sql/sp_head.cc'
--- a/sql/sp_head.cc	2010-06-08 08:58:19 +0000
+++ b/sql/sp_head.cc	2010-10-08 05:21:40 +0000
@@ -50,17 +50,7 @@ static void reset_start_time_for_sp(THD 
   */
   if (!thd->in_sub_stmt)
   {
-    /*
-      First investigate if there is a cached time stamp
-    */
-    if (thd->user_time)
-    {
-      thd->start_time= thd->user_time;
-    }
-    else
-    {
-      my_micro_time_and_time(&thd->start_time);
-    }
+    thd->set_current_time();
   }
 }
 

=== modified file 'sql/sql_acl.cc'
--- a/sql/sql_acl.cc	2010-07-04 04:02:49 +0000
+++ b/sql/sql_acl.cc	2010-10-08 05:21:40 +0000
@@ -278,6 +278,7 @@ my_bool acl_init(bool dont_read_acl_tabl
     DBUG_RETURN(1); /* purecov: inspected */
   thd->thread_stack= (char*) &thd;
   thd->store_globals();
+  thd->set_time();
   lex_start(thd);
   /*
     It is safe to call acl_reload() since acl_* arrays and hashes which

=== modified file 'sql/sql_base.cc'
--- a/sql/sql_base.cc	2010-07-02 18:30:47 +0000
+++ b/sql/sql_base.cc	2010-10-08 05:21:40 +0000
@@ -9097,10 +9097,12 @@ open_performance_schema_table(THD *thd, 
                 MYSQL_LOCK_IGNORE_FLUSH |
                 MYSQL_LOCK_PERF_SCHEMA);
   TABLE *table;
-  /* Save value that is changed in mysql_lock_tables() */
-  ulonglong save_utime_after_lock= thd->utime_after_lock;
   DBUG_ENTER("open_performance_schema_table");
 
+  /*
+    Protect lock clocks that can be changed in mysql_lock_tables()
+  */
+//  thd->protect_lock_clocks();
   thd->reset_n_backup_open_tables_state(backup);
 
   if ((table= open_ltable(thd, one_table, one_table->lock_type, flags)))
@@ -9128,7 +9130,7 @@ open_performance_schema_table(THD *thd, 
     thd->restore_backup_open_tables_state(backup);
   }
 
-  thd->utime_after_lock= save_utime_after_lock;
+//  thd->unprotect_lock_clocks();
   DBUG_RETURN(table);
 }
 

=== modified file 'sql/sql_class.cc'
--- a/sql/sql_class.cc	2010-07-04 04:02:49 +0000
+++ b/sql/sql_class.cc	2010-10-08 05:21:40 +0000
@@ -600,8 +600,9 @@ THD::THD()
               /* statement id */ 0),
    Open_tables_state(refresh_version), rli_fake(0),
    lock_id(&main_lock_id),
-   user_time(0), in_sub_stmt(0),
+   in_sub_stmt(0),
    sql_log_bin_toplevel(false),
+   user_time(0),
    binlog_table_maps(0), binlog_flags(0UL),
    table_map_for_update(0),
    arg_of_last_insert_id_function(FALSE),
@@ -639,7 +640,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;
@@ -658,7 +658,10 @@ THD::THD()
   lex->current_select= 0;
   start_time=(time_t) 0;
   start_utime= prior_thr_create_utime= 0L;
-  utime_after_lock= 0L;
+  reset_query_timer();
+  reset_exec_timer();
+  reset_lock_timer();
+  reset_after_lock_timer();
   current_linfo =  0;
   slave_thread = 0;
   bzero(&variables, sizeof(variables));
@@ -3013,6 +3016,7 @@ void THD::reset_n_backup_open_tables_sta
   DBUG_ENTER("reset_n_backup_open_tables_state");
   backup->set_open_tables_state(this);
   reset_open_tables_state();
+  protect_lock_timers();
   state_flags|= Open_tables_state::BACKUPS_AVAIL;
   DBUG_VOID_RETURN;
 }
@@ -3031,6 +3035,7 @@ void THD::restore_backup_open_tables_sta
               prelocked_mode == NON_PRELOCKED &&
               m_reprepare_observer == NULL);
   set_open_tables_state(backup);
+  unprotect_lock_timers();
   DBUG_VOID_RETURN;
 }
 

=== modified file 'sql/sql_class.h'
--- a/sql/sql_class.h	2010-07-04 04:02:49 +0000
+++ b/sql/sql_class.h	2010-10-08 05:21:40 +0000
@@ -1273,6 +1273,89 @@ struct Ha_data
   Ha_data() :ha_ptr(NULL) {}
 };
 
+/*
+  A Stopwatch implementation.
+
+  NOTE: Please make sure the calling sequence:
+
+    stopwatch.reset(); // make sure stopwatch is in the initial state
+    stopwatch.start();
+    // do some stuff here;
+    stopwatch.stop();
+    stopwatch.get();
+
+  You can call reset() at any time to put the stopwatch in the initial
+  state.
+
+  TODO: Current implementation will not work correctly if user or
+  program like NTP adjusted the time during the timing period.
+*/
+class Stopwatch {
+public:
+  Stopwatch()
+    : start_utime(0), stop_utime(0), is_protected(0)
+  {}
+
+  void start()
+  {
+    if (is_protected)
+      return;
+    DBUG_ASSERT(start_utime == 0 && stop_utime == 0);
+    start_utime= my_micro_time();
+  }
+
+  void stop()
+  {
+    if (is_protected)
+      return;
+    if (!start_utime)
+      return;
+    stop_utime= my_micro_time();
+    /*
+      If user or program like NTP adjusted the time backward,
+      stop_utime could be smaller than start_utime, we will assume
+      stop_utime is the same as start_utime in this case.
+    */
+    if (stop_utime < start_utime)
+      stop_utime= start_utime;
+  }
+
+  void reset()
+  {
+    if (is_protected)
+      return;
+    start_utime= stop_utime= 0;
+  }
+
+  /* Protect stopwatch from being modified */
+  void protect()
+  {
+    is_protected= TRUE;
+  }
+
+  void unprotect()
+  {
+    is_protected= FALSE;
+  }
+
+  /* Get the time interval after stopped the stopwatch */
+  ulonglong get()
+  {
+    /* Return 0 if watch has not yet stopped */
+    if (!stop_utime)
+      return 0;
+    return stop_utime - start_utime;
+  }
+
+private:
+  ulonglong start_utime, stop_utime;
+  bool is_protected;
+};
+
+inline ulong micro_to_seconds(ulonglong time)
+{
+  return time / 1000000;
+}
 
 /**
   @class THD
@@ -1414,10 +1497,9 @@ 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;
+  ulonglong  start_utime;
   
   thr_lock_type update_lock_default;
   Delayed_insert *di;
@@ -1468,6 +1550,35 @@ public:
 
 private:
   /*
+    This is the time when the query starts.
+    
+    Please note that this will not be changed by SET TIMESTAMP
+    statement.
+  */
+  time_t     start_time;
+  /* This is the value set by SET TIMESTAMP statement. */
+  time_t user_time;
+  /*
+    Stopwatch for the query execution time, including time spent on
+    locking and binlogging
+  */
+  Stopwatch query_stopwatch;
+  /*
+    Stopwatch for the query execution time, including time spent on
+    locking, but not including time spent on binlogging. This is used
+    for the exec_time in the binlog events.
+   */
+  Stopwatch exec_stopwatch;
+  /* Stopwatch for the time on locking */
+  Stopwatch lock_stopwatch;
+  /*
+    Stopwatch forthe query execution time after aquired locks,
+    including time spent on binlogging. This is used to recognize slow
+    queries.
+  */
+  Stopwatch after_lock_stopwatch;
+
+  /*
     Number of outstanding table maps, i.e., table maps in the
     transaction cache.
   */
@@ -1832,7 +1943,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;
@@ -2013,29 +2124,117 @@ 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_user_time() { return user_time ? user_time : start_time; }
+  inline time_t query_start_time() { return start_time; }
+  inline void set_start_time(time_t t) { start_time= t; }
+  inline void set_user_time(time_t t) { user_time= t; }
+
+  inline void reset_query_timer()
+  {
+    query_stopwatch.reset();
+  }
+  inline void start_query_timer()
+  {
+    query_stopwatch.reset();
+    query_stopwatch.start();
+  }
+  inline void stop_query_timer()
+  {
+    query_stopwatch.stop();
+  }
+  inline ulonglong get_query_utime()
+  {
+    return query_stopwatch.get();
+  }
+  inline void reset_after_lock_timer()
+  {
+    after_lock_stopwatch.reset();
+  }
+  inline void start_after_lock_timer()
+  {
+    after_lock_stopwatch.reset();
+    after_lock_stopwatch.start();
+  }
+  inline void stop_after_lock_timer()
+  {
+    after_lock_stopwatch.stop();
+  }
+  inline void protect_lock_timers()
+  {
+    lock_stopwatch.protect();
+    after_lock_stopwatch.protect();
+  }
+  inline void unprotect_lock_timers()
+  {
+    lock_stopwatch.unprotect();
+    after_lock_stopwatch.unprotect();
+  }
+  inline ulonglong get_after_lock_utime()
+  {
+    return after_lock_stopwatch.get();
+  }
+  inline void reset_exec_timer()
+  {
+    exec_stopwatch.reset();
+  }
+  inline void start_exec_timer()
+  {
+    exec_stopwatch.reset();
+    exec_stopwatch.start();
+  }
+  inline void stop_exec_timer()
+  {
+    exec_stopwatch.stop();
+  }
+  inline ulong get_exec_time()
+  {
+    return micro_to_seconds(exec_stopwatch.get());
+  }
+  inline void reset_lock_timer()
+  {
+    lock_stopwatch.reset();
+  }
+  inline void start_lock_timer()
+  {
+    lock_stopwatch.reset();
+    lock_stopwatch.start();
+  }
+  inline void stop_lock_timer()
+  {
+    lock_stopwatch.stop();
+  }
+  inline ulong get_lock_utime()
+  {
+    return lock_stopwatch.get();
+  }
   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= my_micro_time_and_time(&start_time);
+    start_query_timer();
+    start_after_lock_timer();
+    start_exec_timer();
+    start_lock_timer();
+  }
+  inline void	set_current_time()
+  {
+    set_start_time(my_time(MY_WME));
+    start_exec_timer();
   }
-  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();
   }
   /*TODO: this will be obsolete when we have support for 64 bit my_time_t */
   inline bool	is_valid_time() 
   { 
     return (start_time < (time_t) MY_TIME_T_MAX); 
   }
-  void set_time_after_lock()  { utime_after_lock= my_micro_time(); }
+  void set_time_after_lock()
+  {
+    stop_lock_timer();
+    start_after_lock_timer();
+  }
   ulonglong current_utime()  { return my_micro_time(); }
   inline ulonglong found_rows(void)
   {
@@ -3092,6 +3291,7 @@ public:
   void cleanup();
 };
 
+
 /* Bits in sql_command_flags */
 
 #define CF_CHANGES_DATA		1

=== modified file 'sql/sql_insert.cc'
--- a/sql/sql_insert.cc	2010-03-29 02:32:30 +0000
+++ b/sql/sql_insert.cc	2010-10-08 05:21:40 +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_time();
   /*
     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
@@ -2508,6 +2507,7 @@ pthread_handler_t handle_delayed_insert(
   pthread_mutex_lock(&LOCK_thread_count);
   thd->thread_id= thd->variables.pseudo_thread_id= thread_id++;
   thd->set_current_time();
+  thd->protect_lock_timers();
   threads.append(thd);
   thd->killed=abort_loop ? THD::KILL_CONNECTION : THD::NOT_KILLED;
   pthread_mutex_unlock(&LOCK_thread_count);
@@ -2640,8 +2640,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-07-04 04:02:49 +0000
+++ b/sql/sql_parse.cc	2010-10-08 05:21:40 +0000
@@ -1543,7 +1543,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_time() - server_start_time)))
       queries_per_second1000= 0;
     else
       queries_per_second1000= thd->query_id * LL(1000) / uptime;
@@ -1699,10 +1699,10 @@ void log_slow_statement(THD *thd)
   */
   if (thd->enable_slow_log)
   {
-    ulonglong end_utime_of_query= thd->current_utime();
+    thd->stop_after_lock_timer();
     thd_proc_info(thd, "logging slow query");
 
-    if (((end_utime_of_query - thd->utime_after_lock) >
+    if (((thd->get_after_lock_utime()) >
          thd->variables.long_query_time ||
          ((thd->server_status &
            (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
@@ -1713,7 +1713,7 @@ void log_slow_statement(THD *thd)
       thd_proc_info(thd, "logging slow query");
       thd->status_var.long_query_count++;
       slow_log_print(thd, thd->query(), thd->query_length(), 
-                     end_utime_of_query);
+                     thd->current_utime());
     }
   }
   DBUG_VOID_RETURN;
@@ -5715,7 +5715,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_plugin.cc'
--- a/sql/sql_plugin.cc	2010-06-10 20:16:43 +0000
+++ b/sql/sql_plugin.cc	2010-10-08 05:21:40 +0000
@@ -1371,6 +1371,7 @@ static void plugin_load(MEM_ROOT *tmp_ro
   }
   new_thd->thread_stack= (char*) &tables;
   new_thd->store_globals();
+  new_thd->set_time();
   lex_start(new_thd);
   new_thd->db= my_strdup("mysql", MYF(0));
   new_thd->db_length= 5;

=== modified file 'sql/sql_show.cc'
--- a/sql/sql_show.cc	2010-07-07 09:15:58 +0000
+++ b/sql/sql_show.cc	2010-10-08 05:21:40 +0000
@@ -1860,7 +1860,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_time();
         thd_info->query=0;
         /* Lock THD mutex that protects its data when looking at it. */
         pthread_mutex_lock(&tmp->LOCK_thd_data);
@@ -1965,8 +1965,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_time() ?
+                                        now - tmp->query_start_time() : 0), FALSE);
       /* STATE */
 #ifndef EMBEDDED_LIBRARY
       val= (char*) (tmp->locked ? "Locked" :


Attachment: [text/bzr-bundle] bzr/zhenxing.he@sun.com-20101008052140-zemhi2rhk0qkgasf.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3470) Bug#52704He Zhenxing8 Oct
  • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3470) Bug#52704Luís Soares15 Oct
    • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:3470)Bug#52704He Zhenxing15 Oct