Microsecond Support for MySQL Slow Logs

Blog    Contact    Sitemap

This web site is no longer maintained.  Read why.

Microsecond Support for MySQL Slow Logs

This document summarizes microsecond resolution support for the MySQL slow query log. MySQL has not always supported microsecond resolution for slow query logging. The first major appearance of such support was in late 2006 by the experts at MySQL Performance Blog. Since then, their patch has been officially integrated into newer versions of MySQL and they have written patches for older versions of MySQL.

Summary of Official Support

v4.0, 4.1, 5.0: not supported; long_query_time is limited to a resolution of 1 to 10 seconds.

v5.1 up to and including 5.1.20: not supported; long_query_time is limited to a resolution of 1 to 10 seconds.

5.1.21+: for the value of long_query_time "the minimum is 0, and a resolution of microseconds is supported when logging to a file. However, the microseconds part is ignored and only integer values are written when logging to tables." (MySQL :: MySQL 5.1 Reference Manual :: 5.2.5 The Slow Query Log)

6.0 up to and including 6.0.3: not supported; long_query_time is limited to a resolution of 1 to 10 seconds.

6.0.4+: for the value of long_query_time "the minimum is 0, and a resolution of microseconds is supported when logging to a file. However, the microseconds part is ignored and only integer values are written when logging to tables." (MySQL :: MySQL 6.0 Reference Manual :: 5.2.5 The Slow Query Log)

Microsecond Resolution: What & Why

A microsecond, denoted by the symbol µs, is one millionth of a second. That means 1 µs is equal to 0.000001 second. This is not to be confused with a millisecond (denoted by 'ms') which is one thousandth of a second, or 0.001 second.

Obviously, the change from second to microsecond resolution support for long_query_time is huge. Microsecond resolution allows a realistic logging of slow queries. In most high-end applications, even 1 full second is too long. Therefore, developers, DBAs and hackers alike think in much finer terms: milliseconds and microseconds.

In reality, query optimization is most often done in milliseconds rather than microseconds. Whereas a 1 second query can be painfully long, a 1 millisecond query is better than most queries can achieve. Regardless, the maximum resolution is in microseconds because this is the resolution provided by the underlying code.

1 s vs. 1 ms vs. 1 µs At A Glance

Since microsecond slow logging in MySQL is relatively new, I have not seen many applications which make the clear distinction between 1 second, 1 millisecond and 1 microsecond. Some "legacy" applications if ran on a new version of MySQL supporting microsecond resolution may show unwieldy values, for example: 0.025000 s instead of 25 ms.

At a glance, the distinction between these three resolutions is:

0.000000 - 0.000999 s = 0 - 999 µs
0.001000 - 0.999999 s = 1 ms - 999.999 ms
1.000000 - n.nnnnnn s = 1 s - n.nnnnnn s

Presently, mysqlreport v3.5+ formats the value of long_query_time shown on the Slow line of its report (line 16) according the proper distinction, displaying µ, ms or s. Eventually, mysqlsla will do the same, too.

Microslow (msl) Logs

Microslow (msl) logs were created by the people at MySQL Performance Blog. Microslow logs are basic MySQL microsecond slow logs plus 10 to 16 additional meta-properties.

An msl log entry looks like (line numbers added for reference):

      1  # User@Host: user[user] @ host []
      2  # Thread_id: 1  Schema: db
      3  # Query_time: 0.000000  Lock_time: 0.000000  Rows_sent: 0 Rows_examined: 0
      4  # QC_Hit: Yes  Full_scan: No  Full_join: Yes  Tmp_table: No  Tmp_table_on_disk: Yes
      5  # Filesort: Yes  Filesort_on_disk: No  Merge_passes: 10
      6  #   InnoDB_IO_r_ops: 11  InnoDB_IO_r_bytes: 12  InnoDB_IO_r_wait: 13.000000
      7  #   InnoDB_rec_lock_wait: 14.000000  InnoDB_queue_wait: 15.000000
      8  #   InnoDB_pages_distinct: 16
      9  SELECT bananas FROM fruits;

 

Lines 2, 4 and 5 show the first 10 additional meta-properties which are always logged. Lines 6, 7 and 8 show the 6 additional InnoDB-related meta-properties which are logged if the query used an InnoDB table; otherwise a singe line is logged which says:

      6  # No InnoDB statistics available for this query

 

These additional meta-properties are excellent additions to the basic MySQL slow log. Unfortunately, msl logs are not officially supported in any version of MySQL. To get them, you must patch your server. An installation walk-through was written to describe how.

To my knowledge, there is no script which can parse msl logs, but one is being created: mysqlsla v2. Watch the Hack MySQL news for updates; I expect to release mysqlsla v2 in early June, 2008.

Microsecond Support for MySQL Slow Logs was last updated May 21, 2008.