MDEV-13727 top-level query timestamp reset at stored func/trigger internal statements

Being executed under slow_log is ON the test revealed a "side-effect" in MDEV-8305 implementation which inadvertently made the trigger or stored function statements to reset the top-level query's THD::start_time et al. (Details of the test failure analysis are footnoted). Unlike the SP case the SF and Trigger's internal statement should not do that. Fixed with revising the MDEV-8305 decision to backup/reset/restore the session timestamp inside sp_instr_stmt::execute(). The timestamp actually remains reset in the SP case by its caller per statement basis by ever existing logics. Timestamps related tests are extended to cover the trigger and stored function case. Note, commit 3395ab7 is reverted as its struct QUERY_START_TIME_INFO declaration is not in use anymore after this patch. Footnote: -------- Specifically to the failing test, a query on the master was logged okay with a timestamp of the query's top-level statement but its post update trigger managed to compute one more (later) timestamp which got inserted into another table. The latter table master-vs-slave no fractional part 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.

Author: andrelkin

mysql-test/main/func_time.result

@@ -3511,3 +3511,29 @@ id	select_type	table	type	possible_keys	key	key_len	ref	rows	filtered	Extra
 1	SIMPLE	NULL	NULL	NULL	NULL	NULL	NULL	NULL	NULL	No tables used
 Warnings:
 Note	1003	select TIMESTAMP'2001-01-01 10:20:30' + interval '10' year AS `c1`,TIMESTAMP'2001-01-01 10:20:30' + interval '10' year AS `c2`,TIMESTAMP'2001-01-01 10:20:30' + interval '10' year AS `c3`
+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;

mysql-test/main/func_time.test

@@ -2077,3 +2077,61 @@ EXPLAIN EXTENDED SELECT
  TIMESTAMP'2001-01-01 10:20:30' + INTERVAL '10' YEAR AS c1,
  INTERVAL '10' YEAR + TIMESTAMP'2001-01-01 10:20:30' AS c2,
  +INTERVAL '10' YEAR + TIMESTAMP'2001-01-01 10:20:30' AS c3;
+
+############
+# 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
+###################

sql/sp_head.cc

@@ -3473,7 +3473,6 @@ 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()));
@@ -3483,15 +3482,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))
- {
- /*
- 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();
- }
+ save_enable_slow_log= thd->enable_slow_log;
  thd->store_slow_query_state(&backup_state);
 
  if (!(res= alloc_query(thd, m_query.str, m_query.length)) &&
@@ -3555,9 +3546,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());
 }

sql/sql_class.h

@@ -2139,26 +2139,6 @@ struct wait_for_commit
  void reinit();
 };
 
-/*
- Structure to store the start time for a query
-*/
-
-struct QUERY_START_TIME_INFO
-{
- my_time_t start_time;
- ulong start_time_sec_part;
- ulonglong start_utime, utime_after_lock;
-
- void backup_query_start_time(QUERY_START_TIME_INFO *backup)
- {
- *backup= *this;
- }
- void restore_query_start_time(QUERY_START_TIME_INFO *backup)
- {
- *this= *backup;
- }
-};
-
 extern "C" void my_message_sql(uint error, const char *str, myf MyFlags);
 
 /**
@@ -2177,8 +2157,7 @@ class THD :public Statement,
  */
  public Item_change_list,
  public MDL_context_owner,
- public Open_tables_state,
- public QUERY_START_TIME_INFO
+ public Open_tables_state
 {
 private:
  inline bool is_stmt_prepare() const
@@ -2403,10 +2382,12 @@ class THD :public Statement,
  uint32 file_id;// for LOAD DATA INFILE
  /* remote (peer) port */
  uint16 peer_port;
+ my_time_t start_time; // start_time and its sec_part 
+ ulong start_time_sec_part; // are almost always used separately
  my_hrtime_t user_time;
  // track down slow pthread_create
  ulonglong prior_thr_create_utime, thr_create_utime;
- ulonglong utime_after_query;
+ ulonglong start_utime, utime_after_lock, utime_after_query;
 
  // Process indicator
  struct {