revision-id: 0768dcbbde546a4665e9607b2de3509b995c2b14 (mariadb-10.3.6-103-g0768dcbbde5) parent(s): 1d296fa18a875248a91ba03f1e84c497223cfd33 author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-05-21 22:10: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. --- sql/sp_head.cc | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/sql/sp_head.cc b/sql/sp_head.cc index 1c1e11ab90c..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,6 +3481,13 @@ sp_instr_stmt::execute(THD *thd, uint *nextp) thd->profiling.set_query_source(m_query.str, m_query.length); #endif + // 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) { /*