Hello Andrei, In LOGGER::slow_log_print() there is a piece of this code: query_utime= (current_utime - thd->start_utime); lock_utime= (thd->utime_after_lock - thd->start_utime); my_hrtime_t current_time= { hrtime_from_time(thd->start_time) + thd->start_time_sec_part + query_utime }; If we don't reset thd->start_utime in the beginning of sp_instr_stmt::execute(), then this code will calculate something useless. It seems that this function: bool LOGGER::slow_log_print( THD *thd, const char *query, size_t query_length, ulonglong current_utime) should not use thd->start_time, thd->start_utime, thd->start_time_sec_part. and should get this information from the argument: bool LOGGER::slow_log_print( THD *thd, const char *query, size_t query_length, const QUERY_START_TIME_INFO *start, ulonglong current_utime) And sp_instr_stmt::execute() should not do thd->set_time(). The whole logic should reside in sql_parse.cc. 1. Remember the current time 2. Execute the statement 3. Log the query if it was slow, using the time remembered at step 1. Is my understanding correct? Thanks. On 04/19/2018 03:42 PM, andrei.elkin@pp.inet.fi wrote:

revision-id: 602865f9f242a7ed5e3679af60a78698c03d93f5 (mariadb-10.3.6-14-g602865f9f24) parent(s): 02e897ca57168059c6a74d1129158afea93aa875 author: Andrei Elkin committer: Andrei Elkin timestamp: 2018-04-18 13:04:46 +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 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 discrepancy became evident thanks to different execution time of the trigger combined with the fact of the logged master timestamp in the micro-second fraction format was truncated on the slave. The latter means the slave execution of the query always started earlier than on the master as far as the timestamp was concerned. And when the fractional part was close to 1 the 2nd timestamp acquired by MDEV-8305 piece of logics could overflow to next integer value. That's how the master table appeared to be temporarly behind the slave's one.

Fixed with restoring the pre-MDEV-8305 behavior not to reset the current statement's timestamp when the query is not from a stored procedure. That is the trigger's or stored function's queries continue to use the top-level statement's timestamp as they are supposed to.

--- mysql-test/main/func_time.result | 26 ++++++++++++++++++ mysql-test/main/func_time.test | 59 ++++++++++++++++++++++++++++++++++++++++ sql/sp_head.cc | 4 +-- 3 files changed, 87 insertions(+), 2 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 f7847bae89d..90fe77e6158 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -3471,7 +3471,7 @@ 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)) + 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 @@ -3544,7 +3544,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()); _______________________________________________ commits mailing list commits@mariadb.org https://lists.askmonty.org/cgi-bin/mailman/listinfo/commits