Below is the list of changes that have just been committed into a local
5.1 repository of mleich. When mleich does a push these changes
will be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html
ChangeSet@stripped, 2008-05-22 19:56:38+02:00, mleich@stripped +2 -0
Fix for
Bug#36345 Test 'func_misc' fails on RHAS3 x86_64
and a second similar problem within this test found
during experimenting.
mysql-test/r/func_misc.result@stripped, 2008-05-22 19:55:34+02:00, mleich@stripped +62 -27
Updated results
mysql-test/t/func_misc.test@stripped, 2008-05-22 19:55:34+02:00, mleich@stripped +281 -22
Modifications
diff -Nrup a/mysql-test/r/func_misc.result b/mysql-test/r/func_misc.result
--- a/mysql-test/r/func_misc.result 2008-03-15 19:28:17 +01:00
+++ b/mysql-test/r/func_misc.result 2008-05-22 19:55:34 +02:00
@@ -104,41 +104,76 @@ t1 CREATE TABLE `t1` (
`length(uuid())` int(10) NOT NULL DEFAULT '0'
) ENGINE=MyISAM DEFAULT CHARSET=latin1
drop table t1;
-create table t1 (a timestamp default '2005-05-05 01:01:01',
+create table t1 (id int,
+a timestamp default '2005-05-05 01:01:01',
b timestamp default '2005-05-05 01:01:01');
-insert into t1 set a = now();
+insert into t1 set id = 1,a = now();
select sleep(3);
sleep(3)
0
-update t1 set b = now();
-select timediff(b, a) >= '00:00:03' from t1;
-timediff(b, a) >= '00:00:03'
+update t1 set b = now() where id = 1;
+insert into t1 set id = 2,a = now();
+select sleep(3);
+sleep(3)
+0
+update t1 set b = now() where id = 2;
+select count(*) >= 1 from t1
+where timediff(b, a) between '00:00:03' and '00:00:07';
+count(*) >= 1
1
drop table t1;
-set global query_cache_size=1355776;
-create table t1 (a int);
-insert into t1 values (1),(1),(1);
-create table t2 (a datetime default null, b datetime default null);
-insert into t2 set a = now();
-select a from t1 where sleep(1);
-a
-update t2 set b = now() where b is null;
-insert into t2 set a = now();
-select a from t1 where sleep(a);
-a
-update t2 set b = now() where b is null;
-insert into t2 set a = now();
-select a from t1 where sleep(1);
-a
-update t2 set b = now() where b is null;
-select timediff(b, a) >= '00:00:03' from t2;
-timediff(b, a) >= '00:00:03'
-1
+SET @@global.query_cache_size = 1024 * 64;
+SELECT 1 as some_value, sleep(1);
+some_value sleep(1)
+1 0
+SELECT <Qcache_queries_in_cache_before> = <Qcache_queries_in_cache_before>
+AS "Was the query not cached (= expectation)?";
+Was the query not cached (= expectation)?
1
+DROP TEMPORARY TABLE IF EXISTS proclist_history;
+DROP TABLE IF EXISTS t1;
+CREATE TEMPORARY TABLE proclist_history AS
+SELECT 'Bug 1' AS test, 0 AS attempt, NOW() AS observation_time, state, time
+FROM information_schema.processlist WHERE 1 = 0;
+CREATE TABLE t1 (f1 BIGINT);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t1 VALUES (1);
+INSERT INTO t1 VALUES (1);
+SET @sleep_time_per_result_row = 1;
+----- establish connection con1 (user = root) -----
+SET @sleep_time_per_result_row = 1;
+Qcache_queries_in_cache: 0
+# Send query with send, pull server responses later
+SELECT sleep(@sleep_time_per_result_row) FROM t1;
+----- switch to connection default (user = root) -----
+----- switch to connection con1 (user = root) -----
+# Pull server responses of last query
+sleep(@sleep_time_per_result_row)
+0
+0
+0
+0
+----- switch to connection con1 (user = root) -----
+# Send query with send, pull server responses later
+SELECT sleep(@sleep_time_per_result_row) FROM t1;
+----- switch to connection default (user = root) -----
+SELECT COUNT(*) FROM information_schema.processlist
+WHERE info = 'SELECT sleep(@sleep_time_per_result_row) FROM t1'
+ AND state = 'User sleep';
+COUNT(*)
1
-drop table t2;
-drop table t1;
-set global query_cache_size=default;
+----- switch to connection con1 (user = root) -----
+# Pull server responses of last query
+sleep(@sleep_time_per_result_row)
+0
+0
+0
+0
+----- switch to connection default and close connection con1 -----
+SET @@global.query_cache_size = default;
+DROP TABLE t1;
+DROP TEMPORARY TABLE proclist_history;
create table t1 select INET_ATON('255.255.0.1') as `a`;
show create table t1;
Table Create Table
diff -Nrup a/mysql-test/t/func_misc.test b/mysql-test/t/func_misc.test
--- a/mysql-test/t/func_misc.test 2008-03-15 19:28:17 +01:00
+++ b/mysql-test/t/func_misc.test 2008-05-22 19:55:34 +02:00
@@ -105,34 +105,293 @@ drop table t1;
#
# Bug #6760: Add SLEEP() function
#
-create table t1 (a timestamp default '2005-05-05 01:01:01',
+# Note (mleich):
+# --------------
+# The experiments around
+# Bug#36345 Test 'func_misc' fails on RHAS3 x86_64
+# showed that the original test for Bug#6760 produced false alarms in case
+# of parallel system time decreases. It was therefore modified.
+# Solution:
+# We run the test two times and assume a pass if at least one attempt
+# is successful. The disadvantage is that a parallel "unnatural" increase of
+# system time (set time via ntpd etc.) is able to hide a wrong working SLEEP
+# function. This is no problem because
+# - such changes of the system are rare
+# - there is an extreme high probability that either the following test
+# or the frequent runs of the current test on the current testing box or
+# other boxes catch a wrong working SLEEP function.
+create table t1 (id int,
+ a timestamp default '2005-05-05 01:01:01',
b timestamp default '2005-05-05 01:01:01');
-insert into t1 set a = now();
+insert into t1 set id = 1,a = now();
select sleep(3);
-update t1 set b = now();
-select timediff(b, a) >= '00:00:03' from t1;
+update t1 set b = now() where id = 1;
+insert into t1 set id = 2,a = now();
+select sleep(3);
+update t1 set b = now() where id = 2;
+# Check that the timediff caused by the length of the sleep is not plain wrong.
+# We can have delays in statement processing of 1 - 2 seconds on
+# an overloaded testing box.
+# Minimum (= ideal) real timediff = '00:00:03'
+# Maximum acceptable real timediff = '00:00:07'
+select count(*) >= 1 from t1
+where timediff(b, a) between '00:00:03' and '00:00:07';
drop table t1;
-#
+################################################################################
# Bug #12689: SLEEP() gets incorrectly cached/optimized-away
#
-set global query_cache_size=1355776;
-create table t1 (a int);
-insert into t1 values (1),(1),(1);
-create table t2 (a datetime default null, b datetime default null);
-insert into t2 set a = now();
-select a from t1 where sleep(1);
-update t2 set b = now() where b is null;
-insert into t2 set a = now();
-select a from t1 where sleep(a);
-update t2 set b = now() where b is null;
-insert into t2 set a = now();
-select a from t1 where sleep(1);
-update t2 set b = now() where b is null;
-select timediff(b, a) >= '00:00:03' from t2;
-drop table t2;
-drop table t1;
-set global query_cache_size=default;
+# Description from bug report (slightly modified)
+# ===============================================
+# Bug 1 (happened all time):
+# SELECT * FROM t1 WHERE SLEEP(1) will only result in a sleep of 1
+# second, regardless of the number of rows in t1.
+# Bug 2 (happened all time):
+# Such a query will also get cached by the query cache, but should not.
+#
+# Notes (mleich, May 2008)
+# ========================
+# 1. The testcase for this bug had to be reimplemented because of
+# Bug#36345 Test 'func_misc' fails on RHAS3 x86_64
+# - Bad effect: We did not reach the expected time differences.
+# - Experiments showed that for example a parallel change of the system
+# time (decrease of time value) like via ntpd provokes this effect.
+#
+# It is a clear error within the setup of the testing environment if
+# tests relying on derivates of the system time can meet parallel
+# manipulations of this time. Covering these weaknesses by workarounds
+# within the tests is often not perfect doable at all and costs
+# significant development and/or runtime per test.
+#
+# Results of experiments with/without manipulation of system time:
+# ----------------------------------------------------------------
+# Definition: Predicted_cumulative_sleep_time =
+# #_of_result_rows * sleep_time_per_result_row
+# processlist.time refers to the session in state 'User sleep'
+#
+# 1. Total (real sleep time) ~= predicted_cumulative_sleep_time !!
+# 2. processlist.time behaves "synchronous" to system time and NOW() and
+# shows also the "jumps" caused by system time manipulations
+# 3. processlist.time is unsigned, the next value below 0 is ~ 4G
+# 4. Current processlist.time ~= current real sleep time
+# if the system time was not manipulated
+#
+# 2. How to reveal the absence of Bug 1:
+#
+# The state of a session within the PROCESSLIST changes to 'User sleep'
+# if the sessions runs a statement containing the sleep function and the
+# processing of the statement is just within the phase where the sleep
+# is done.
+#
+# As soon as the "Real" time where the session is in state 'User sleep'
+# exceeds the sleep_time_per_result_row we can be sure that the execution
+# of the query slept more time than needed for just one row.
+#
+# "Real" time in state 'User sleep' > sleep_time_per_result_row
+#
+# Estimation 1:
+# -------------
+# n = how often we observed the session is in state 'User sleep'
+#
+# "Real" time in state 'User sleep'
+# = (n - 1) * sleep_time_in_loop
+# + time needed for the execution of the statements within the loop
+# (includes the time waiting for getting resources like CPU etc.
+# which si significant in case of high load on testing box)
+#
+# (n - 1) * sleep_time_in_loop >= sleep_time_per_result_row
+#
+# n >= sleep_time_per_result_row / sleep_time_in_loop + 1
+#
+# Simplification taking truncation of values etc. into account:
+# n >= sleep_time_per_result_row / sleep_time_in_loop + 2
+#
+# We cannot have met Bug 1 if
+# n >= sleep_time_per_result_row / sleep_time_in_loop + 2
+# is fulfilled.
+# But there is a significant risk that a run on an overloaded box
+# does not reach the estimated limit.
+#
+# Estimation 2:
+# -------------
+# processlist.time should show how long a session is within the current
+# state. I verified by experimenting that this value is not reset per
+# row of the the result set.
+#
+# "Real" time in state 'User sleep'
+# >= highest observed value of processlist.time
+#
+# We cannot have met Bug 1 if
+# highest observed value of processlist.time > sleep_time_per_result_row
+# is fulfilled.
+# Unfortunately processlist.time is no more reliable in case of parallel
+# changes of the system time.
+#
+# Final solution:
+# ---------------
+# Run a subtest with "judging" based on estimation 1. If the limit is not
+# reached, assume that we suffered from high load and try estimation 2.
+# If estimation 2 gets cheated by parallel increase of system time
+# assume that later runs on the same box or other boxes will show if
+# Bug#12689 occured again.
+#
+# 3. How to reveal the absence of Bug 2:
+# - By checking the behaviour during second execution:
+# We run the same statement again and meet the session at least once in
+# state 'User sleep'.
+# - By checking secondary information (query cache statistics)
+# The first execution of the statment must not cause that
+# Qcache_queries_in_cache is incremented.
+#
+# 4. We do not run
+# --source include/have_query_cache.inc
+# at the beginning of this script because we want that this script is not
+# skipped if the query cache is disabled. This means the detection of wrongly
+# cached queries is in such cases without real effect.
+#
+# 5. Thanks to Davi for excellent hints and ideas.
+#
+################################################################################
+
+# 1. For Bug 2: Qcache_queries_in_cache must be not incremented if a query with
+# sleep was first time executed.
+SET @@global.query_cache_size = 1024 * 64;
+let $Qcache_queries_in_cache_before =
+ query_get_value(SHOW STATUS LIKE 'Qcache_queries_in_cache', Value, 1);
+SELECT 1 as some_value, sleep(1);
+let $Qcache_queries_in_cache_after =
+ query_get_value(SHOW STATUS LIKE 'Qcache_queries_in_cache', Value, 1);
+# Show that the query with sleep was not cached via query cache statistics.
+--replace_result $Qcache_queries_in_cache_before <Qcache_queries_in_cache_before> $Qcache_queries_in_cache_after <Qcache_queries_in_cache_after>
+eval SELECT $Qcache_queries_in_cache_before = $Qcache_queries_in_cache_after
+ AS "Was the query not cached (= expectation)?";
+#
+# 2. For Bug 1: Estimation 1
+# Real sleep time must exceed the sleep time for just one row.
+#
+let $sleep_time_per_result_row = 1;
+let $row_count = 4;
+
+--disable_warnings
+DROP TEMPORARY TABLE IF EXISTS proclist_history;
+DROP TABLE IF EXISTS t1;
+--enable_warnings
+CREATE TEMPORARY TABLE proclist_history AS
+SELECT 'Bug 1' AS test, 0 AS attempt, NOW() AS observation_time, state, time
+FROM information_schema.processlist WHERE 1 = 0;
+CREATE TABLE t1 (f1 BIGINT);
+let $num = $row_count;
+while ($num)
+{
+ INSERT INTO t1 VALUES (1);
+ dec $num;
+}
+
+eval SET @sleep_time_per_result_row = $sleep_time_per_result_row;
+let $sleep_command = SELECT sleep(@sleep_time_per_result_row) FROM t1;
+
+# Set wait_timeout to a useful small value.
+let $wait_timeout= `SELECT $row_count * $sleep_time_per_result_row + 5`;
+let $wait_condition =
+ SELECT COUNT(*) >= @sleep_time_per_result_row / 0.1 + 2
+ FROM proclist_history WHERE Test = 'Bug 1';
+
+--echo ----- establish connection con1 (user = root) -----
+connect (con1,localhost,root,,);
+eval SET @sleep_time_per_result_row = $sleep_time_per_result_row;
+let $Qcache_queries_in_cache_before =
+ query_get_value(SHOW STATUS LIKE 'Qcache_queries_in_cache', Value, 1);
+--echo Qcache_queries_in_cache: $Qcache_queries_in_cache_before
+--echo # Send query with send, pull server responses later
+send;
+eval $sleep_command;
+#
+--echo ----- switch to connection default (user = root) -----
+connection default;
+#
+--disable_query_log
+let $wait_counter= `SELECT $wait_timeout * 10`;
+let $wait_condition_reps= 0;
+while ($wait_counter)
+{
+ let $success= `$wait_condition`;
+ inc $wait_condition_reps;
+ eval
+ INSERT INTO proclist_history
+ ( test, attempt, observation_time, state, time)
+ SELECT 'Bug 1', $wait_condition_reps, NOW(), state, time
+ FROM information_schema.processlist
+ WHERE info = '$sleep_command';
+ if ($success)
+ {
+ let $wait_counter= 0;
+ }
+ if (!$success)
+ {
+ real_sleep 0.1;
+ dec $wait_counter;
+ }
+}
+--enable_query_log
+if (!$success)
+{
+ # Estimation 1 had no success - We are most probably on a testing box
+ # running under high load.
+ # Try Estimation 2:
+ let $success = `SELECT MAX(time) > @sleep_time_per_result_row
+ FROM proclist_history WHERE test = 'Bug 1'`;
+}
+if (!$success)
+{
+ --echo # ------------------------------------------------------------
+ --echo # The check for
+ --echo # Bug#12689: SLEEP() gets incorrectly cached/optimized-away
+ --echo # failed. None of both estimations are fulfilled.
+ --echo #
+ --echo # Dumping debug information
+ --echo #
+ --echo # Estimation 1:
+ eval $wait_condition;
+ --echo # ------------------------------------------------------------
+ --echo # Estimation 2:
+ SELECT MAX(time) > @sleep_time_per_result_row
+ FROM proclist_history WHERE test = 'Bug 1';
+ --echo # ------------------------------------------------------------
+ SELECT attempt, observation_time, state, time FROM proclist_history
+ WHERE test = 'Bug 1' ORDER BY attempt;
+ --echo # ------------------------------------------------------------
+}
+--echo ----- switch to connection con1 (user = root) -----
+connection con1;
+--echo # Pull server responses of last query
+reap;
+#
+# 3. For Bug 2: A second execution of the same statement must again show
+# the session in state 'User sleep'.
+--echo ----- switch to connection con1 (user = root) -----
+connection con1;
+--echo # Send query with send, pull server responses later
+send;
+eval $sleep_command;
+#
+--echo ----- switch to connection default (user = root) -----
+connection default;
+let $wait_condition = SELECT COUNT(*) FROM information_schema.processlist
+ WHERE info = '$sleep_command'
+ AND state = 'User sleep';
+--source include/wait_condition.inc
+# Simply show that we reached the expected state.
+eval $wait_condition;
+--echo ----- switch to connection con1 (user = root) -----
+connection con1;
+--echo # Pull server responses of last query
+reap;
+--echo ----- switch to connection default and close connection con1 -----
+connection default;
+disconnect con1;
+SET @@global.query_cache_size = default;
+DROP TABLE t1;
+DROP TEMPORARY TABLE proclist_history;
#
# Bug #21466: INET_ATON() returns signed, not unsigned
| Thread |
|---|
| • bk commit into 5.1 tree (mleich:1.2616) BUG#36345 | mleich | 22 May |
