[Commits] 602865f9f24: MDEV-13727 rpl.rpl_concurrency_error failed

andrei.elkin at pp.inet.fi andrei.elkin at pp.inet.fi
Wed Apr 18 15:00:19 EEST 2018


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());


More information about the commits mailing list