revision-id: 6f3c27eb59a04041e4dbbeae8231c0aafdc967e5 (mariadb-10.3.6-102-g6f3c27eb59a) parent(s): 73a10cbcc5178ae5378abb821428d35d3276b4da author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-05-22 09:38:14 +0300 message: MDEV-13727 top-level query timestamp reset at stored func/trigger internal statements Being executed under slow_log is ON the test revealed a "side-effect" in MDEV-8305 implementation which inadvertently made the trigger or stored function statements to reset the top-level query's THD::start_time et al. (Details of the test failure analysis are footnoted). Unlike the SP case the SF and Trigger's internal statement should not do that. Fixed with refining the MDEV-8305 decision to reset the session timestamp with consulting the sub-statement type flag. Timestamps related tests are extended to cover the trigger and stored function case. Footnote: -------- Specifically to the failing test, a query on the master was logged okay with a timestamp of the query's top-level statement but its post update trigger managed to compute one more (later) timestamp which got inserted into another table. The latter table master-vs-slave no fractional part 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. --- mysql-test/main/func_time.result | 26 ++++++++++++++++++ mysql-test/main/func_time.test | 59 ++++++++++++++++++++++++++++++++++++++++ sql/sp_head.cc | 18 ++++++++++-- 3 files changed, 100 insertions(+), 3 deletions(-) diff --git a/mysql-test/main/func_time.result b/mysql-test/main/func_time.result index 2772f850ce9..9babfc6a48b 100644 --- a/mysql-test/main/func_time.result +++ b/mysql-test/main/func_time.result @@ -3484,3 +3484,29 @@ 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 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// +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; +SET @@session.slow_query_log= @sav_slow_query_log; +DROP FUNCTION fn_sleep_before_now; +DROP TRIGGER trg_insert_t_ts; +DROP TABLE t_ts, t_trig; diff --git a/mysql-test/main/func_time.test b/mysql-test/main/func_time.test index 5417cb20a92..ad207218969 100644 --- a/mysql-test/main/func_time.test +++ b/mysql-test/main/func_time.test @@ -2057,3 +2057,62 @@ 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. +# + +CREATE TABLE t_ts (a timestamp(6)); +CREATE TABLE t_trig (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// +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 +} + +# Cleanup +SET @@session.slow_query_log= @sav_slow_query_log; +DROP FUNCTION fn_sleep_before_now; +DROP TRIGGER trg_insert_t_ts; +DROP TABLE t_ts, t_trig; + +# +# End of MDEV-13727 +################### diff --git a/sql/sp_head.cc b/sql/sp_head.cc index edaa4de942e..c5c69bc8614 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -1690,6 +1690,9 @@ sp_head::execute_trigger(THD *thd, MEM_ROOT call_mem_root; Query_arena call_arena(&call_mem_root, Query_arena::STMT_INITIALIZED_FOR_SP); Query_arena backup_arena; + // Alternative MDEV-13727 fixes + // bool save_enable_slow_log; + DBUG_ENTER("sp_head::execute_trigger"); DBUG_PRINT("info", ("trigger %s", m_name.str)); @@ -1758,8 +1761,10 @@ sp_head::execute_trigger(THD *thd, } thd->spcont= nctx; - + // save_enable_slow_log= thd->enable_slow_log; + // thd->enable_slow_log= false; err_status= execute(thd, FALSE); + // thd->enable_slow_log= save_enable_slow_log; err_with_cleanup: thd->restore_active_arena(&call_arena, &backup_arena); @@ -3476,7 +3481,14 @@ 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)) + // Todo: remove upon review + // Fixme: alternatively `thd->enable_slow_log' could be set to `false' + // by grand-caller similarly to how it's done to the SP case + // by + // commit 21518ab2e4538e1a6c9b3a136a93885a98492218 + // Author: Monty <monty@mariadb.org> + // Date: Fri Jul 21 19:56:41 2017 +0300 + if ((save_enable_slow_log= thd->enable_slow_log) && !thd->in_sub_stmt) { /* Save start time info for the CALL statement and overwrite it with the @@ -3549,7 +3561,7 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) } } /* Restore the original query start time */ - if (thd->enable_slow_log) + if (thd->enable_slow_log && !thd->in_sub_stmt) thd->restore_query_start_time(&time_info); DBUG_RETURN(res || thd->is_error());