#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(¤t_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
