Patch: microslow_innodb

This patch adds microsecond time resolution and additional statistics to the slow query log output. It lets you enable or disable the slow query log at runtime, adds logging for the slave SQL thread, and adds fine-grained control over what and how much to log into the slow query log.

The ability to log queries with microsecond precision is essential for measuring the work the MySQL server performs. The standard slow query log in MySQL 5.0 has only 1-second granularity, which is too coarse for all but the slowest queries. MySQL 5.1 has microsecond resolution, but does not have the extra information about query execution that is included in the Percona patches.

You can use Maatkit's mk-query-digest tool to aggregate similar queries together and report on those that consume the most execution time.

The patch provides the following variables:

Filters the slow log by the query's execution plan. The value is a comma-delimited string, and can contain any combination of the following values:

Values are OR'ed together. If the string is empty, then the filter is disabled. If it is not empty, then queries will only be logged to the slow log if their execution plan matches one of the types of plans present in the filter.

For example, to log only queries that perform a full table scan, set the value to “full_scan”. To log only queries that use on-disk temporary storage for intermediate results, set the value to “tmp_table_on_disk,filesort_on_disk”.

Specifies that only a fraction of sessions should be logged. Logging is enabled for every nth session. By default, n is 1, so logging is enabled for every session. Rate limiting is disabled for the replication thread.

Logging all queries might consume I/O bandwidth and cause the log file to grow large. This option lets you log full sessions, so you have complete records of sessions for later analysis; but you can rate-limit the number of sessions that are logged. For example, if you set the value to 100, then one percent of sessions will be logged in their entirety. Note that this feature will not work well if your application uses any type of connection pooling or persistent connections.

Specifies how much information to include in your slow log. The value is a comma-delimited string, and can contain any combination of the following values:

Values are OR'ed together.

For example, to enable microsecond query timing and InnoDB statistics, set this option to “microtime,innodb”.

Specifies the time threshold for filtering queries out of the slow query log. The unit of time is seconds. This option has the same meaning as in a standard MySQL server, with the following changes:

• The option accepts fractional values. If set to 0.5, for example, queries longer than 1/2 second will be logged.
• If the value is set to 0, then all queries are logged. This is different from the standard MySQL build, where a value of 0 disables logging.

Before version 1.01 of this patch, the value was an integer, and the unit of time was microseconds, not seconds.

This variable's behavior is modified by use_global_long_query_time.

Specifies that queries replayed by the slave SQL thread on a MySQL slave will be logged. The standard MySQL server will not log any queries executed by the slave's SQL thread.

To stop or start the logging from the slave thread, you should change the global value, and then execute STOP SLAVE; START SLAVE;. This will destroy and recreate the slave SQL thread, so it will see the newly set global value.

Specifies that only queries that examine more than this number of rows should be logged.

Lets you enable and disable the slow query log online, with no need to restart MySQL. The standard MySQL server does not permit this until version 5.1.

Shows the file name of the current slow query log file. It is read-only for safety.

If 1 is set, global long_query_time is always used instead of the local long_query_time, and the local long_query_time is updated by global when used. 0 is same as normal behavior. (default 0)

The patch adds more information to the slow log output. Here is a sample log entry:

# User@Host: mailboxer[mailboxer] @  [192.168.10.165]
# Thread_id: 11167745  Schema: board
# QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: Yes  Disk_tmp_table: No
# Filesort: Yes  Disk_filesort: No  Merge_passes: 0
# Query_time: 0.000659  Lock_time: 0.000070  Rows_sent: 0  Rows_examined: 30  Rows_affected: 0  Rows_read: 30
#   InnoDB_IO_r_ops: 1  InnoDB_IO_r_bytes: 16384  InnoDB_IO_r_wait: 0.028487
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 5
select count(distinct author_id) from art87.article87 force index (forum_id) where forum_id = 240215 and thread_id = '710575' 

The patch makes the following changes:

Each slow log entry now contains a connection identifier, so you can trace all the queries coming from a single connection. This is the same value that is shown in the Id column in SHOW FULL PROCESSLIST or returned from the CONNECTION_ID() function.

Each entry also contains a schema name, so you can trace all the queries whose default database was set to a particular schema.

# Thread_id: 11167745  Schema: board

This is the original functionality offered by the microslow patch. Query_time and Lock_time are logged with microsecond resolution.

The patch also adds information about how many rows were examined for SELECT queries, and how many were analyzed and affected for UPDATE, DELETE, and INSERT queries.

# Query_time: 0.000659  Lock_time: 0.000070  Rows_sent: 0  Rows_examined: 30  Rows_affected: 0  Rows_read: 30

Each query can be executed in various ways. For example, it may use indexes or do a full table scan, or a temporary table may be needed. These are the things that you can usually see by running EXPLAIN on the query. The patch will now allow you to see the most important facts about the execution in the log file.

# QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: Yes  Disk_tmp_table: No
# Filesort: Yes  Disk_filesort: No  Merge_passes: 0

The values and their meanings are documented with the log_slow_filter option.

The final part of the output is the InnoDB usage statistics. MySQL currently shows many per-session statistics for operations with SHOW SESSION STATUS, but that does not include those of InnoDB, which are always global and shared by all threads. This patch lets you see those values for a given query.

#   InnoDB_IO_r_ops: 1  InnoDB_IO_r_bytes: 16384  InnoDB_IO_r_wait: 0.028487
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 5

If the query did not use InnoDB tables, that information is written into the log instead of the above statistics.

• http://www.mysqlperformanceblog.com/2009/02/10/impact-of-logging-on-mysql%E2%80%99s-performance/
• use_global_long_query_time