Deep Dive into MySQL Slow Query Log: Time, Lock, and Detailed Output Explanation

Background : The article focuses on parsing important parts of MySQL's slow query log rather than how to enable it, referring readers to the official documentation for enabling slow query logging.

1. Time in Slow Query

The recorded time is obtained from the OS using gettimeofday , as shown in the code snippet:

while (gettimeofday(&t, NULL) != 0) {}
newtime = (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
return newtime;

This value is stored in thd->current_utime() and printed with # Time: %s .

2. Criteria for Slow Query Recording

The log records a query as slow based on long_query_time (actual execution time) and optionally log_queries_not_using_indexes and log_slow_admin_statements . The article concentrates on long_query_time .

3. Meaning of long_query_time

The actual consumed time is defined as:

Actual Consumed Time = Execution Time + Lock Wait Time

Only the execution part (excluding lock wait) is compared with long_query_time . The function log_slow_applicable implements this logic:

res = cur_utime - thd->utime_after_lock;
if (res > thd->variables.long_query_time)
    thd->server_status |= SERVER_QUERY_WAS_SLOW;
else
    thd->server_status &= ~SERVER_QUERY_WAS_SLOW;

Thus res (actual execution time) = cur_utime (total time) – utime_after_lock (lock wait time).

4. How MySQL Records Lock Time

Lock time is stored in utime_after_lock at the end of mysql_lock_tables via THD::set_time_after_lock :

void set_time_after_lock() {
    utime_after_lock = my_micro_time();
    MYSQL_SET_STATEMENT_LOCK_TIME(m_statement_psi, (utime_after_lock - start_utime));
}

InnoDB records lock wait time through thd_storage_lock_wait :

void thd_storage_lock_wait(THD *thd, longlong value) {
    thd->utime_after_lock += value;
}

5. Percona log_slow_verbosity Parameter

The parameter controls which fields appear in the slow log. Options include microtime , query_plan , innodb , minimal , standard , and full . Setting it to full yields the most detailed output.

6. Detailed Output Sections

The slow‑log entry consists of several parts, each generated by specific code:

Time : # Time: %s

User@Host : # User@Host: %s Id: %s

Schema, Error, Killed : # Schema: %s Last_errno: %u Killed: %u

Execution Info : Query time, lock time, rows sent/examined/affected, bytes sent, temporary tables, etc.

Optimizer Info : QC_Hit, Full_scan, Full_join, Tmp_table, Filesort, etc.

InnoDB Stats : IO reads, lock waits, distinct pages.

Timestamp : SET timestamp=... derived from current_utime .

Each field’s source code is shown, illustrating how MySQL assembles the log line.

7. Summary

The article concludes that the slow‑query log records the execution time after subtracting lock wait time, and each output field maps to a specific variable or function in the MySQL source, providing a clear reference for developers who need to debug performance issues.