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.
| MySQL Version | Comments |
|---|---|
| 4.1.x | Limited functionality available: only microsecond resolution, no added statistics. |
| 5.0.x | Full functionality available. |
| 5.1.x | Microsecond resolution included in official MySQL server; patch adds statistics. |
The patch provides the following variables:
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
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:
| Value | Explanation |
|---|---|
| qc_miss | The query was not found in the query cache. |
| full_scan | The query performed a full table scan. |
| full_join | The query performed a full join (a join without indexes). |
| tmp_table | The query created an implicit internal temporary table. |
| tmp_table_on_disk | The query's temporary table was stored on disk. |
| filesort | The query used a filesort. |
| filesort_on_disk | The filesort was performed on disk. |
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”.
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
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.
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
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:
| Value | Explanation |
|---|---|
| microtime | Log queries with microsecond precision (mandatory). |
| query_plan | Log information about the query's execution plan (optional). |
| innodb | Log InnoDB statistics (optional). |
| full | Equivalent to all other values OR'ed together. |
Values are OR'ed together.
For example, to enable microsecond query timing and InnoDB statistics, set this option to “microtime,innodb”.
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
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:
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.
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
| Notes | As of release 5.0.68-percona-3, this is only a command-line variable (TBD whether it is dynamic in later releases) |
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.
| Type | System and command-line variable |
| Scope | Session, Global |
| Dynamic | Yes |
Specifies that only queries that examine more than this number of rows should be logged.
| Type | System and command-line variable |
| Scope | Global |
| Dynamic | Yes |
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.
| Type | System variable |
| Scope | Global |
| Dynamic | No |
Shows the file name of the current slow query log file. It is read-only for safety.
| Type | System variable |
| Scope | Global |
| Dynamic | Yes |
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
| Name | Description | Context |
|---|---|---|
| Rows_examined | Number of rows scanned | SELECT |
| Rows_affected | Number of rows changed | UPDATE, DELETE, INSERT |
| Rows_read | Number of rows read | UPDATE, DELETE, INSERT |
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
| Name | Description |
|---|---|
| InnoDB_IO_r_ops | Counts the number of page read operations scheduled. The actual number of read operations may be different, but since this can be done asynchronously, there is no good way to measure it. |
| InnoDB_IO_r_bytes | Similar to InnoDB_IO_r_ops, but the unit is bytes. |
| InnoDB_IO_r_wait | Shows how long (in seconds) it took InnoDB to actually read the data from storage. |
| InnoDB_rec_lock_wait | Shows how long (in seconds) the query waited for row locks. |
| InnoDB_queue_wait | Shows how long (in seconds) the query spent either waiting to enter the InnoDB queue or inside that queue waiting for execution. |
| InnoDB_pages_distinct | Counts approximately the number of unique pages the query accessed. The approximation is based on a small hash array representing the entire buffer pool, because it could take a lot of memory to map all the pages. The inaccuracy grows with the number of pages accessed by a query, becuase there is a higher probability of hash collisions. |
If the query did not use InnoDB tables, that information is written into the log instead of the above statistics.
| Author/Origin | Maciej Dobrzanski, Percona |
| Bugs fixed | |
| Dependencies |
Discussion
An issue we find with the slow log is that when doing long multi-INSERT or REPLACE statements that can potentially take a few seconds, those also get logged. This means that the slow log grows too much (those statments/log-lines can be VERY long). This makes the log hard to read but it also effectively makes mysql to do double the amount of write work when inserting data (one to its db layer and one more to the log!)
I propose 2 types of filters added:
log_slow_row_limit = 4192 # log no more than 4192 characters per row / statement log_slow_inserts=0 # completely disable insert and replace statements logging to the slow log