#At file:///media/sdb2/hezx/work/mysql/bzr/b52704/5.1-bugteam/ based on revid:li-bing.song@stripped
3470 He Zhenxing 2010-07-16
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:
mysql-test/r/information_schema.result
mysql-test/t/information_schema.test
sql/field.cc
sql/item_timefunc.cc
sql/log.cc
sql/log_event.cc
sql/log_event.h
sql/set_var.cc
sql/sp_head.cc
sql/sql_class.cc
sql/sql_class.h
sql/sql_insert.cc
sql/sql_parse.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-07-16 09:03:03 +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-07-16 09:03:03 +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-16 09:03:03 +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-16 09:03:03 +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-07-16 09:03:03 +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/field.cc'
--- a/sql/field.cc 2010-07-02 18:30:47 +0000
+++ b/sql/field.cc 2010-07-16 09:03:03 +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-16 09:03:03 +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-07-02 18:30:47 +0000
+++ b/sql/log.cc 2010-07-16 09:03:03 +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-07-08 02:44:26 +0000
+++ b/sql/log_event.cc 2010-07-16 09:03:03 +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;
}
@@ -2446,7 +2446,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
@@ -4334,7 +4335,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-07-04 04:02:49 +0000
+++ b/sql/log_event.h 2010-07-16 09:03:03 +0000
@@ -1006,9 +1006,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-07-02 18:30:47 +0000
+++ b/sql/set_var.cc 2010-07-16 09:03:03 +0000
@@ -2738,14 +2738,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/sp_head.cc'
--- a/sql/sp_head.cc 2010-06-08 08:58:19 +0000
+++ b/sql/sp_head.cc 2010-07-16 09:03:03 +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_class.cc'
--- a/sql/sql_class.cc 2010-07-04 04:02:49 +0000
+++ b/sql/sql_class.cc 2010-07-16 09:03:03 +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-07-04 04:02:49 +0000
+++ b/sql/sql_class.h 2010-07-16 09:03:03 +0000
@@ -1414,7 +1414,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;
@@ -1467,6 +1466,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.
@@ -1832,7 +1832,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,22 +2013,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();
}
/*TODO: this will be obsolete when we have support for 64 bit my_time_t */
inline bool is_valid_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-16 09:03:03 +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-07-04 04:02:49 +0000
+++ b/sql/sql_parse.cc 2010-07-16 09:03:03 +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() - server_start_time)))
queries_per_second1000= 0;
else
queries_per_second1000= thd->query_id * LL(1000) / uptime;
@@ -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_show.cc'
--- a/sql/sql_show.cc 2010-07-07 09:15:58 +0000
+++ b/sql/sql_show.cc 2010-07-16 09:03:03 +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();
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() ?
+ now - tmp->query_start() : 0), FALSE);
/* STATE */
#ifndef EMBEDDED_LIBRARY
val= (char*) (tmp->locked ? "Locked" :
Attachment: [text/bzr-bundle] bzr/zhenxing.he@sun.com-20100716090303-zjrclckbvmqeb9lp.bundle
