[MDEV-11628] mysql.slow_log reports incorrect start time Created: 2016-12-21  Updated: 2024-01-25  Resolved: 2024-01-23

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 5.5.53, 5.5, 10.0, 10.1, 10.0.28, 10.1.20, 10.2, 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3, 11.4
Fix Version/s: 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Minor
Reporter: Nirbhay Choubey (Inactive) Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: logging, patch, upstream

Issue Links:
Relates
relates to MDEV-33267 User with minimal permissions can int... Closed

 Description   

MariaDB [test]> truncate mysql.slow_log;
Query OK, 0 rows affected (0.00 sec)
 
MariaDB [test]> select current_time(); select sleep(10); select current_time();
+----------------+
| current_time() |
+----------------+
| 17:24:37       |
+----------------+
1 row in set (0.00 sec)
 
+-----------+
| sleep(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.00 sec)
 
+----------------+
| current_time() |
+----------------+
| 17:24:47       |
+----------------+
1 row in set (0.00 sec)
 
MariaDB [test]> select start_time, sql_text from mysql.slow_log;
+----------------------------+-------------------------+
| start_time                 | sql_text                |
+----------------------------+-------------------------+
| 2016-12-21 17:24:15.320518 | truncate mysql.slow_log |
| 2016-12-21 17:24:37.593565 | select current_time()   |
| 2016-12-21 17:24:47.595008 | select sleep(10)        | <-- Start time is ~10sec after previous command
| 2016-12-21 17:24:47.596239 | select current_time()   |
+----------------------------+-------------------------+
4 rows in set (0.00 sec)



 Comments   
Comment by Nirbhay Choubey (Inactive) [ 2016-12-21 ]

diff --git a/sql/log.cc b/sql/log.cc
index 569942a..b46d6d6 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -1317,8 +1317,8 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
     DBUG_ASSERT(thd->start_time);
     query_utime= (current_utime - thd->start_utime);
     lock_utime=  (thd->utime_after_lock - thd->start_utime);
-    my_hrtime_t current_time= { hrtime_from_time(thd->start_time) +
-                                thd->start_time_sec_part + query_utime };
+    my_hrtime_t start_time= { hrtime_from_time(thd->start_time) +
+                              thd->start_time_sec_part };
 
     if (!query)
     {
@@ -1328,7 +1328,7 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
     }
 
     for (current_handler= slow_log_handler_list; *current_handler ;)
-      error= (*current_handler++)->log_slow(thd, current_time,
+      error= (*current_handler++)->log_slow(thd, start_time,
                                             user_host_buff, user_host_len,
                                             query_utime, lock_utime, is_command,
                                             query, query_length) || error;

Generated at Thu Feb 08 07:51:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.