Bug #98274 mysql.slow_log start_time varies with time_zone setting
Submitted: 17 Jan 2020 16:11 Modified: 4 Mar 2020 12:31
Reporter: andy zhang Email Updates:
Status: Not a Bug Impact on me:
Category:MySQL Server: Data Types Severity:S4 (Feature request)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any
Tags: slow_log time_zone

[17 Jan 2020 16:11] andy zhang
When log_output = 'TABLE', mysql.slow_log is used to track slow query. The start_time value varies with the time_zone system variable change.

Consumer of mysql.slow_log could be confused on the real time of slow query, especially for an international company across different time zones.

How to repeat:
set global slow_query_log = ON;
set global log_output='TABLE';
set time_zone = '+8:00';
select sleep(20);
set time_zone = '+6:00';
select sleep(20);

select start_time from mysql.slow_log;  // you will see 2 rows with huge gap of start_time

Suggested fix:
diff --git a/sql/log.cc b/sql/log.cc
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -100,6 +100,7 @@
 #include "sql/table.h"  // TABLE_FIELD_TYPE
 #include "thr_lock.h"
 #include "thr_mutex.h"
+#include "sql/tztime.h"  // Time_zone
 #ifdef _WIN32
 #include "sql/message.h"
@@ -921,6 +922,17 @@ bool Log_to_csv_event_handler::log_slow(
   bool save_time_zone_used = thd->time_zone_used;

+  /*
+   Export start_time in GMT format when required
+  */
+  Time_zone * save_time_zone = thd->variables.time_zone;
+  if (slow_log_in_gmt)
+    thd->variables.time_zone = my_tz_OFFSET0;
+  DBUG_EXECUTE_IF("simulate_original_slow_log_format",
+                  {thd->variables.time_zone = save_time_zone;});
                         SLOW_LOG_NAME.str, SLOW_LOG_NAME.length,
                         SLOW_LOG_NAME.str, TL_WRITE_CONCURRENT_INSERT);
@@ -1061,6 +1073,7 @@ err:
   if (need_close) close_log_table(thd, &open_tables_backup);

   thd->time_zone_used = save_time_zone_used;
+  thd->variables.time_zone = save_time_zone;
diff --git a/sql/mysqld.cc b/sql/mysqld.cc
--- a/sql/mysqld.cc
+++ b/sql/mysqld.cc
+bool slow_log_in_gmt = false;

diff --git a/sql/mysqld.h b/sql/mysqld.h
--- a/sql/mysqld.h
+++ b/sql/mysqld.h
+extern bool slow_log_in_gmt;

 enum enum_binlog_error_action {
diff --git a/sql/sys_vars_ext.cc b/sql/sys_vars_ext.cc
--- a/sql/sys_vars_ext.cc
+++ b/sql/sys_vars_ext.cc
@@ -573,6 +573,12 @@
+static Sys_var_bool Sys_slow_log_in_gmt(
+    "slow_log_in_gmt", "When it's on, write start_time column of mysql.slow_log in GMT "
+    "time_zone .",
+    READ_ONLY GLOBAL_VAR(slow_log_in_gmt), CMD_LINE(OPT_ARG),
+    DEFAULT(false));
[27 Jan 2020 13:55] MySQL Verification Team
Hello Mr. zhang,

Thank you for your feature request.

Before we analyse whether this feature request is acceptable, we do require to know which version and release of MySQL are you using ....

Thank you in advance ......
[1 Feb 2020 8:58] andy zhang

I did the test against 8.0.13. 

[3 Feb 2020 13:27] MySQL Verification Team
Hi Mr. Zhang,

I must confess that your request is not clear to me.

At this particular moment, time is different across all timezones. Hence, I do not see how can we have the same time in all timezones. That beats the purpose of the timezone.

Also, if slow log behaves differently in "FILE" mode, let us know.

Last, but not least, 8.0.13 is too old release, so please try 8.0.19.
[4 Mar 2020 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".