[Commits] 99c40e0628d: MDEV-13727 rpl.rpl_concurrency_error failed

andrei.elkin at pp.inet.fi andrei.elkin at pp.inet.fi
Wed Apr 25 14:20:20 EEST 2018


revision-id: 99c40e0628d1157a835d0225d2810637774c9174 (mariadb-10.3.6-26-g99c40e0628d)
parent(s): 38c799c9a5e5aadd3f4df157a4151dd1f71d5bcb
author: Andrei Elkin
committer: Andrei Elkin
timestamp: 2018-04-25 14:16:38 +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 which was 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 whole seconds 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.

Fixed with slight refactoring of MDEV-8305 to reuse always existing
timestamp resetting mechanism engaged prior to a stored procedure's
next statement execution.
Now the resetter is augmented to also deal with THD::start_utime et al.

---
 mysql-test/main/func_time.result | 35 +++++++++++++++++++
 mysql-test/main/func_time.test   | 75 ++++++++++++++++++++++++++++++++++++++++
 sql/sp_head.cc                   | 22 +-----------
 3 files changed, 111 insertions(+), 21 deletions(-)

diff --git a/mysql-test/main/func_time.result b/mysql-test/main/func_time.result
index 2772f850ce9..4a999280159 100644
--- a/mysql-test/main/func_time.result
+++ b/mysql-test/main/func_time.result
@@ -3484,3 +3484,38 @@ 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 TABLE t1   (a timestamp(6));
+CREATE TABLE t2   (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//
+CREATE PROCEDURE sp()
+BEGIN
+INSERT INTO t1 SET a=current_timestamp(6);
+INSERT INTO t2 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;
+CALL sp();
+SET @@session.slow_query_log= @sav_slow_query_log;
+DROP PROCEDURE sp;
+DROP FUNCTION fn_sleep_before_now;
+DROP TRIGGER trg_insert_t_ts;
+DROP TABLE t_ts, t_trig, t1, t2;
diff --git a/mysql-test/main/func_time.test b/mysql-test/main/func_time.test
index 5417cb20a92..9f44761d938 100644
--- a/mysql-test/main/func_time.test
+++ b/mysql-test/main/func_time.test
@@ -2057,3 +2057,78 @@ 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.
+# In contrast the current timestamp of stored procedure
+# monotonically grows from statement to statement.
+
+CREATE TABLE t_ts   (a timestamp(6));
+CREATE TABLE t_trig (a timestamp(6));
+CREATE TABLE t1   (a timestamp(6));
+CREATE TABLE t2   (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//
+CREATE PROCEDURE sp()
+BEGIN
+  INSERT INTO t1 SET a=current_timestamp(6);
+  INSERT INTO t2 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
+}
+
+CALL sp();
+if (!`SELECT t2.a > t1.a FROM t1,t2`)
+{
+  SELECT t1.a, t2.a FROM t1,t2;
+  --die Error: timestamps must be growing monotonically
+}
+
+# Cleanup
+SET @@session.slow_query_log= @sav_slow_query_log;
+DROP PROCEDURE sp;
+DROP FUNCTION fn_sleep_before_now;
+DROP TRIGGER trg_insert_t_ts;
+DROP TABLE t_ts, t_trig, t1, t2;
+
+#
+# End of MDEV-13727
+###################
diff --git a/sql/sp_head.cc b/sql/sp_head.cc
index f7847bae89d..ac3e490e598 100644
--- a/sql/sp_head.cc
+++ b/sql/sp_head.cc
@@ -66,7 +66,7 @@ extern "C" uchar *sp_table_key(const uchar *ptr, size_t *plen, my_bool first);
 static void reset_start_time_for_sp(THD *thd)
 {
   if (!thd->in_sub_stmt)
-    thd->set_start_time();
+    thd->set_time();
 }
 
 
@@ -3459,9 +3459,7 @@ int
 sp_instr_stmt::execute(THD *thd, uint *nextp)
 {
   int res;
-  bool save_enable_slow_log;
   const CSET_STRING query_backup= thd->query_string;
-  QUERY_START_TIME_INFO time_info;
   Sub_statement_state backup_state;
   DBUG_ENTER("sp_instr_stmt::execute");
   DBUG_PRINT("info", ("command: %d", m_lex_keeper.sql_command()));
@@ -3471,15 +3469,6 @@ 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))
-  {
-    /*
-      Save start time info for the CALL statement and overwrite it with the
-      current time for log_slow_statement() to log the individual query timing.
-    */
-    thd->backup_query_start_time(&time_info);
-    thd->set_time();
-  }
   thd->store_slow_query_state(&backup_state);
 
   if (!(res= alloc_query(thd, m_query.str, m_query.length)) &&
@@ -3515,12 +3504,6 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
       if (log_slow)
         log_slow_statement(thd);
 
-      /*
-        Restore enable_slow_log, that can be changed by a admin or call
-        command
-      */
-      thd->enable_slow_log= save_enable_slow_log;
-
       /* Add the number of rows to thd for the 'call' statistics */
       thd->add_slow_query_state(&backup_state);
     }
@@ -3543,9 +3526,6 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
       thd->get_stmt_da()->reset_diagnostics_area();
     }
   }
-  /* Restore the original query start time */
-  if (thd->enable_slow_log)
-    thd->restore_query_start_time(&time_info);
 
   DBUG_RETURN(res || thd->is_error());
 }


More information about the commits mailing list