| Bug #114620 | Inconsistency in the query time metric of the slow log | ||
|---|---|---|---|
| Submitted: | 11 Apr 2024 6:47 | Modified: | 11 Apr 2024 10:43 |
| Reporter: | Chi Zhang | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server | Severity: | S3 (Non-critical) |
| Version: | 8.0.36 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | slow log | ||
[11 Apr 2024 10:43]
MySQL Verification Team
Hi Mr. Zhang, Thank you for your bug report. First of all, let us inform you that this is a forum for the reports with the fully repeatable test cases. Your report does not contain one. Next, it is important to note that SQL statement is finished only when the result is returned to the client-side. Last, but not least, the intention of the slow query calculus is to calculate, as much as it is possible, the real time that query took to execute. It is possible that many users do not know how to properly configure MySQL server, so that the wait for the resources is minimised. Not a bug.
Description: In the MySQL code, when determining whether to record the slow log, the server calculates the query time and compares it with long_query_time, as shown in the following: ####sql/sql_class.cc##### void THD::update_slow_query_status() { if (my_micro_time() > start_utime + variables.long_query_time) server_status |= SERVER_QUERY_WAS_SLOW; } ######################### When the slow log is recorded, the query time is calculated again, as shown in the following figure. ########sql/log.cc####### bool Query_logger::slow_log_write(THD *thd, const char *query, size_t query_length, bool aggregate, ulonglong lock_usec, ulonglong exec_usec) { ...... const ulonglong current_utime = my_micro_time(); ulonglong query_utime, lock_utime; if (aggregate) { query_utime = exec_usec; lock_utime = lock_usec; } else if (thd->start_utime) { query_utime = (current_utime - thd->start_utime); lock_utime = thd->get_lock_usec(); } else { query_utime = 0; lock_utime = 0; } ...... } ######################### As a result, in a high-concurrency environment, the query time recorded in the slow log may be greatly different from the user experience. It is better to record the time before the result is returned for later judgment and recording. How to repeat: In a high-concurrency environment, it is feasible to compare the actual query time with the time recorded in the slow log. But the better way is with the help of gdb debugging, you can find this problem obviously.