From 72b623eef0b21e56bc59805de9b14d4854083556 Mon Sep 17 00:00:00 2001 From: "First_name Last_name mleich@mysql.com" <> Date: Fri, 23 May 2008 17:23:55 +0200 Subject: [PATCH] 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 | 89 +++++++--- mysql-test/t/func_misc.test | 303 +++++++++++++++++++++++++++++++--- 2 files changed, 343 insertions(+), 49 deletions(-) diff --git a/mysql-test/r/func_misc.result b/mysql-test/r/func_misc.result index a6b912b4e0a..d53bb92bbc0 100644 --- a/mysql-test/r/func_misc.result +++ b/mysql-test/r/func_misc.result @@ -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' +SET @@global.query_cache_size = 1024 * 64; +SELECT 1 as some_value, sleep(1); +some_value sleep(1) +1 0 +SELECT = +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 -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 --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_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