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.el...@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
> comm...@mariadb.org
> https://lists.askmonty.org/cgi-bin/mailman/listinfo/commits
>
_______________________________________________
Mailing list: https://launchpad.net/~maria-developers
Post to : maria-developers@lists.launchpad.net
Unsubscribe : https://launchpad.net/~maria-developers
More help : https://help.launchpad.net/ListHelp
