Fix for

   Bug#36345 Test 'func_misc' fails on RHAS3 x86_64
and a second similar problem within this test found
during experimenting.

1 files changed, 281 insertions, 22 deletions

diff --git a/mysql-test/t/func_misc.test b/mysql-test/t/func_misc.test
index d33dd9b0d14..46f434c9d44 100644
--- a/mysql-test/t/func_misc.test
+++ b/mysql-test/t/func_misc.test
@@ -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