MySQL Bugs: #116814: The mysql.slow_log table uses @@session.time

Bug #116814	The mysql.slow_log table uses @@session.time_zone to record time
Submitted:	28 Nov 2024 3:43	Modified:	28 Nov 2024 9:44
Reporter:	Xizhe Zhang (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	8.0.40	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
When a slow SQL statement is recorded in table 'mysql.slow_log', the 'start_time' field uses @@session.time_zone to convert the timestamp of the statement execution start to the time string of the corresponding time zone. This makes the 'start_time' in the mysql.slow_log table very confusing. The slow_log table itself is often used for alarms, but such confusing time records may even show time that has not yet arrived.

How to repeat:
set time_zone="+08:00";
select sleep(2);

set time_zone="+04:00";
select sleep(2);

set time_zone="+00:00";
select sleep(2);

-- Confusing 'start_time', if I monitor slow_log in time zone 'UTC+00:00', I can even see future statement
select * from mysql.slow_log;;
+----------------------------+------------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
| start_time                 | user_host                          | query_time      | lock_time       | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text        | thread_id |
+----------------------------+------------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
| 2024-11-28 11:22:06.473024 | root[root] @ localhost [127.0.0.1] | 00:00:02.000167 | 00:00:00.000000 |         1 |             1 |    |              0 |         0 |  21558507 | select sleep(2) |      1054 |
| 2024-11-28 07:22:20.167637 | root[root] @ localhost [127.0.0.1] | 00:00:02.000161 | 00:00:00.000000 |         1 |             1 |    |              0 |         0 |  21558507 | select sleep(2) |      1054 |
| 2024-11-28 03:22:28.292648 | root[root] @ localhost [127.0.0.1] | 00:00:02.000152 | 00:00:00.000000 |         1 |             1 |    |              0 |         0 |  21558507 | select sleep(2) |      1054 |
+----------------------------+------------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
3 rows in set (0.00 sec)

Suggested fix:
I think mysql.slow_log needs to use a unified time zone when recording start_time, rather than each session setting its own time_zone at will.

I debugged and found the following stack trace involved in time zone conversion:
#0  Time_zone_offset::gmt_sec_to_TIME (this=0x5642008, tmp=0x7f35d8072970, t=1732763118)
    at tztime.cc:1017
#1  0x0000000001113141 in Time_zone::gmt_sec_to_TIME (tv=..., tmp=0x7f35d8072970, this=0x5642008)
    at ../sql/tztime.h:79
#2  Field_timestampf::get_date_internal_at (this=<optimized out>, tz=0x5642008,
    ltime=0x7f35d8072970) at field.cc:5234
#3  0x0000000001114815 in Field_temporal_with_date::val_str (this=0x7f2b0000ad68,
    val_buffer=0x7f35d80729e0) at field.cc:4760
#4  0x0000000002879094 in ha_tina::encode_quote (this=this@entry=0x7f2b00027060) at ha_tina.cc:556
#5  0x0000000002878f16 in ha_tina::write_row (this=0x7f2b00027060,
    buf=0x7f2b0000cf80 "gG\335\356\n\372\017\"") at ha_tina.cc:943
#6  0x000000000114ef53 in handler::ha_write_row (this=0x7f2b00027060,
    buf=0x7f2b0000cf80 "gG\335\356\n\372\017\"") at handler.cc:8017
#7  0x0000000001353f66 in Log_to_csv_event_handler::log_slow (this=<optimized out>, thd=
    0x7f2c94003f80, current_utime=<optimized out>, query_start_arg=<optimized out>,
    user_host=<optimized out>, user_host_len=<optimized out>, query_utime=<optimized out>,
    lock_utime=<optimized out>, sql_text=<optimized out>, sql_text_len=<optimized out>)
    at log.cc:1129
#8  0x0000000001353ae5 in Query_logger::slow_log_write (this=this@entry=0x46f1960 <query_logger>,
    thd=thd@entry=0x7f2c94003f80, query=0x7f2c94007380 "select sleep(2)", query_length=15,
    aggregate=aggregate@entry=false, lock_usec=lock_usec@entry=0, exec_usec=<optimized out>)

I think it may be necessary to make a special judgment here not to use thd->time_zone() for writing to slow_log:
bool Field_timestamp::get_date_internal(MYSQL_TIME *ltime) const {
  THD *thd = current_thd;
  return get_date_internal_at(thd->time_zone(), ltime);
}

After further thinking, it is possible to modify the time_zone of thd in the function Log_to_csv_event_handler::log_slow first, and then restore it after recording, which may be less invasive to other modules.

Hello Xizhe Zhang,

Thank you for the report and feedback.

regards,
Umesh