maria-developers team mailing list archive

[Alexander Barkov <bar@xxxxxxxxxxx>]

  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@xxxxxxxxxx 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@xxxxxxxxxxx
> https://lists.askmonty.org/cgi-bin/mailman/listinfo/commits
>