revision-id: 99c40e0628d1157a835d0225d2810637774c9174 (mariadb-10.3.6-26-g99c40e0628d) parent(s): 38c799c9a5e5aadd3f4df157a4151dd1f71d5bcb author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-04-25 14:16:38 +0300 message: MDEV-13727 rpl.rpl_concurrency_error failed The test actually revealed a flaw in MDEV-8305 which inadvertently enrolled the trigger and stored function into slow query reporting which was aimed exclusively to the stored procedure. Specifically to the test, a query on the master was logged with a timestamp of the query's top-level statement but its (post update) trigger computed one more (later) timestamp which got inserted into another table. Master-vs-slave whole seconds timestamp discrepancy became evident thanks to different execution time of the trigger combined with the fact of the logged with micro-second fractional part master timestamp was truncated on the slave. On master when the fractional part was close to 1 the trigger execution added up its own latency to overflow to next second value. That's how the master timestamp surprisingly turned out to bigger than the slave's one. Fixed with slight refactoring of MDEV-8305 to reuse always existing timestamp resetting mechanism engaged prior to a stored procedure's next statement execution. Now the resetter is augmented to also deal with THD::start_utime et al. --- mysql-test/main/func_time.result | 35 +++++++++++++++++++ mysql-test/main/func_time.test | 75 ++++++++++++++++++++++++++++++++++++++++ sql/sp_head.cc | 22 +----------- 3 files changed, 111 insertions(+), 21 deletions(-) diff --git a/mysql-test/main/func_time.result b/mysql-test/main/func_time.result index 2772f850ce9..4a999280159 100644 --- a/mysql-test/main/func_time.result +++ b/mysql-test/main/func_time.result @@ -3484,3 +3484,38 @@ t1 CREATE TABLE `t1` ( `c5` varchar(100) DEFAULT NULL ) ENGINE=MyISAM DEFAULT CHARSET=latin1 DROP TABLE t1; +CREATE TABLE t_ts (a timestamp(6)); +CREATE TABLE t_trig (a timestamp(6)); +CREATE TABLE t1 (a timestamp(6)); +CREATE TABLE t2 (a timestamp(6)); +CREATE FUNCTION fn_sleep_before_now() returns int +BEGIN +INSERT INTO t_ts SET a= current_timestamp(6); +RETURN 0; +END// +CREATE TRIGGER trg_insert_t_ts AFTER INSERT ON t_ts FOR EACH ROW +BEGIN +INSERT into t_trig set a= current_timestamp(6); +END// +CREATE PROCEDURE sp() +BEGIN +INSERT INTO t1 SET a=current_timestamp(6); +INSERT INTO t2 SET a=current_timestamp(6); +END// +SET @sav_slow_query_log= @@session.slow_query_log; +SET @@session.slow_query_log= ON; +SELECT current_timestamp(6),fn_sleep_before_now() INTO @ts_cur, @ts_func; +SELECT a FROM t_ts LIMIT 1 into @ts_func; +SELECT a FROM t_trig LIMIT 1 into @ts_trig; +DELETE FROM t_ts; +DELETE FROM t_trig; +SET @@session.slow_query_log= OFF; +SELECT current_timestamp(6),fn_sleep_before_now() INTO @ts_cur, @func_ts; +SELECT a FROM t_ts LIMIT 1 into @ts_func; +SELECT a FROM t_trig LIMIT 1 into @ts_trig; +CALL sp(); +SET @@session.slow_query_log= @sav_slow_query_log; +DROP PROCEDURE sp; +DROP FUNCTION fn_sleep_before_now; +DROP TRIGGER trg_insert_t_ts; +DROP TABLE t_ts, t_trig, t1, t2; diff --git a/mysql-test/main/func_time.test b/mysql-test/main/func_time.test index 5417cb20a92..9f44761d938 100644 --- a/mysql-test/main/func_time.test +++ b/mysql-test/main/func_time.test @@ -2057,3 +2057,78 @@ EXECUTE IMMEDIATE USING NULL, '10', 10, 10.0, 10e0, TIME'10:20:30'; SHOW CREATE TABLE t1; DROP TABLE t1; + + +############ +# MDEV-13727 +# Current timestamp functions inside stored functions must return the +# value of the top-level statement's timestamp (its start time). +# This must hold regardless of @@slow_query_log option. +# In contrast the current timestamp of stored procedure +# monotonically grows from statement to statement. + +CREATE TABLE t_ts (a timestamp(6)); +CREATE TABLE t_trig (a timestamp(6)); +CREATE TABLE t1 (a timestamp(6)); +CREATE TABLE t2 (a timestamp(6)); +delimiter //; +CREATE FUNCTION fn_sleep_before_now() returns int +BEGIN + INSERT INTO t_ts SET a= current_timestamp(6); + RETURN 0; +END// +CREATE TRIGGER trg_insert_t_ts AFTER INSERT ON t_ts FOR EACH ROW +BEGIN + INSERT into t_trig set a= current_timestamp(6); +END// +CREATE PROCEDURE sp() +BEGIN + INSERT INTO t1 SET a=current_timestamp(6); + INSERT INTO t2 SET a=current_timestamp(6); +END// +delimiter ;// + +SET @sav_slow_query_log= @@session.slow_query_log; + +# @@slow_query_log ON check +SET @@session.slow_query_log= ON; +SELECT current_timestamp(6),fn_sleep_before_now() INTO @ts_cur, @ts_func; + +SELECT a FROM t_ts LIMIT 1 into @ts_func; +SELECT a FROM t_trig LIMIT 1 into @ts_trig; +if (!`SELECT @ts_cur = @ts_func AND @ts_func = @ts_trig`) +{ + SELECT @ts_cur, @ts_func, @ts_trig; + --die Error: timestamps must be equal but they diverge +} +DELETE FROM t_ts; +DELETE FROM t_trig; + +# @@slow_query_log OFF check +SET @@session.slow_query_log= OFF; +SELECT current_timestamp(6),fn_sleep_before_now() INTO @ts_cur, @func_ts; +SELECT a FROM t_ts LIMIT 1 into @ts_func; +SELECT a FROM t_trig LIMIT 1 into @ts_trig; +if (!`SELECT @ts_cur = @ts_func AND @ts_func = @ts_trig`) +{ + SELECT @ts_cur, @ts_func, @ts_trig; + --die Error: timestamps must be equal but they diverge +} + +CALL sp(); +if (!`SELECT t2.a > t1.a FROM t1,t2`) +{ + SELECT t1.a, t2.a FROM t1,t2; + --die Error: timestamps must be growing monotonically +} + +# Cleanup +SET @@session.slow_query_log= @sav_slow_query_log; +DROP PROCEDURE sp; +DROP FUNCTION fn_sleep_before_now; +DROP TRIGGER trg_insert_t_ts; +DROP TABLE t_ts, t_trig, t1, t2; + +# +# End of MDEV-13727 +################### diff --git a/sql/sp_head.cc b/sql/sp_head.cc index f7847bae89d..ac3e490e598 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -66,7 +66,7 @@ extern "C" uchar *sp_table_key(const uchar *ptr, size_t *plen, my_bool first); static void reset_start_time_for_sp(THD *thd) { if (!thd->in_sub_stmt) - thd->set_start_time(); + thd->set_time(); } @@ -3459,9 +3459,7 @@ int sp_instr_stmt::execute(THD *thd, uint *nextp) { int res; - bool save_enable_slow_log; const CSET_STRING query_backup= thd->query_string; - QUERY_START_TIME_INFO time_info; Sub_statement_state backup_state; DBUG_ENTER("sp_instr_stmt::execute"); DBUG_PRINT("info", ("command: %d", m_lex_keeper.sql_command())); @@ -3471,15 +3469,6 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) thd->profiling.set_query_source(m_query.str, m_query.length); #endif - if ((save_enable_slow_log= thd->enable_slow_log)) - { - /* - Save start time info for the CALL statement and overwrite it with the - current time for log_slow_statement() to log the individual query timing. - */ - thd->backup_query_start_time(&time_info); - thd->set_time(); - } thd->store_slow_query_state(&backup_state); if (!(res= alloc_query(thd, m_query.str, m_query.length)) && @@ -3515,12 +3504,6 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) if (log_slow) log_slow_statement(thd); - /* - Restore enable_slow_log, that can be changed by a admin or call - command - */ - thd->enable_slow_log= save_enable_slow_log; - /* Add the number of rows to thd for the 'call' statistics */ thd->add_slow_query_state(&backup_state); } @@ -3543,9 +3526,6 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) thd->get_stmt_da()->reset_diagnostics_area(); } } - /* Restore the original query start time */ - if (thd->enable_slow_log) - thd->restore_query_start_time(&time_info); DBUG_RETURN(res || thd->is_error()); }