Microslow patch is used by many DBAs and developers to accurately time their queries and to catch those which run less than a second as they can also be a performance killer for a busy application.
Recently I have started the development of an updated version of the patch. The basic idea is the same as for its predecessor – to get more information about query execution logged into slow log, however the new version is loaded with a set of cool new features.
CONNECTION IDENTIFIER
Each slow log entry now contains a connection identifier, so you can trace all the queries coming from a single connection.
1 | # Thread_id: 4 |
MICROTIME RESOLUTION QUERY TIMING
This is the original functionality offered by Microslow patch. The new edition is free of a tiny bug which was to treat
1 | long_query_time |
value as seconds. In effect one could only choose to log all queries to see those which take less than 1s. Now
1 | long_query_time |
is in microseconds and you can set it for example to 300000 which is 0.3s!
1 | # Query_time: 0.503016 Lock_time: 0.000048 Rows_sent: 56 Rows_examined: 1113 |
LOGGING OF THE REPLICATED STATEMENTS
Normally MySQL will not write into slow log any queries executed by the slave’s SQL thread. This patch allows you to change that behavior with the new parameter
1 | --log-slow-slave-statements |
.
THE DETAILED INFORMATION ABOUT QUERY EXECUTION
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.
1 2 | # QC_Hit: No Full_scan: No Full_join: No Tmp_table: Yes Disk_tmp_table: No # Filesort: Yes Disk_filesort: No Merge_passes: 0 |
1 | QC_Hit |
tells whether query cache hit occurred or not. If it says ‘Yes’, then all other values will be ‘No’ or 0, because the query was not actually executed by the engine.
If
1 | Full_scan |
is set then most likely the query is a bad one, because it read all the rows from a table.
1 | Full_join |
means any of the joins didn’t use indexes.
If a temporary table is required for query execution
1 | Tmp_table |
will be set. Sometimes that table must be created on disk instead of in memory, in such case
1 | Disk_tmp_table |
will state that.
1 | Filesort |
is for indicating that filesort algorithm was used, while
1 | Disk_filesort |
means that sorting was done through temporary files.
INNODB USAGE
The final part are the InnoDB usage statistics. MySQL currently allows you to see many per-session statistics for operations with
1 | SHOW SESSION STATUS |
, but that does not include those of InnoDB, which are always global and shared by all the threads. The patch gives you the opportunity to see those values for a given query.
1 2 3 | # InnoDB_IO_r_ops: 19 InnoDB_IO_r_bytes: 311296 InnoDB_IO_r_wait: 0.382176 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.067538 # InnoDB_pages_distinct: 20 |
1 | InnoDB_IO_r_ops |
is the counter for the number of page read operations scheduled. The acutal number of read operations may be different, but since this can be done asynchronously, unfortunatelly there is no good way to measure that.
1 | InnoDB_IO_r_bytes |
is the corresponding value in bytes.
With
1 | InnoDB_IO_r_wait |
you can see how much time (in seconds) it took InnoDB to actually read the data from storage.
1 | InnoDB_rec_lock_wait |
is the time (in seconds) query had to wait on row locks.
1 | InnoDB_queue_wait |
is the time (in seconds) query spent either waiting to enter the InnoDB queue or inside that queue waiting for execution.
1 | InnoDB_pages_distinct |
tells the number of unique pages accessed by the query. This is actually an approximation 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 as there is more chance for hash collisions.
In case InnoDB is not used for the query execution that information is written into the log instead the above statistics.
The full slow log entry for a query using InnoDB can look like this:
1 2 3 4 5 6 7 8 9 10 | # User@Host: macko[macko] @ localhost [] # Thread_id: 4 # Query_time: 0.503016 Lock_time: 0.000048 Rows_sent: 56 Rows_examined: 1113 # QC_Hit: No Full_scan: No Full_join: No Tmp_table: Yes Disk_tmp_table: No # Filesort: Yes Disk_filesort: No Merge_passes: 0 # InnoDB_IO_r_ops: 19 InnoDB_IO_r_bytes: 311296 InnoDB_IO_r_wait: 0.382176 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.067538 # InnoDB_pages_distinct: 20 SET timestamp=1193841780; SELECT DISTINCT c from sbtest where id between 501895 and 502895 order by c; |
or if InnoDB was not used:
1 2 3 4 5 6 7 | # Time: 071031 20:03:16 # User@Host: macko[macko] @ localhost [] # Thread_id: 12 # Query_time: 0.026385 Lock_time: 0.000158 Rows_sent: 1 Rows_examined: 0 # QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Disk_tmp_table: No # Filesort: No Disk_filesort: No Merge_passes: 0 # No InnoDB statistics available for this query SELECT COUNT(1) FROM t2; |
Important note: Although the patch was tested and run successfully under stress with both synthetic benchmarks and real database traffic, it’s considered experimental and as such I don’t recommend using it in production or on any important system!
The patch is available for MySQL Community 5.0.45 on Linux. May not work on other systems.
Maciek Dobrzanski
Great. I can’t wait to try out the InnoDB IO stats.
We are using now !!
Good patch! A lot of usefull information…
What about backport for MySQL 4.1 ?
If you do a 5.1 version of the patch I’ll include it in the -stew patchset… (although I’m increasingly thinking a 5.0 based patchset could also be useful)
Michael,
The backport to 4.1 may happen, although this is uncertain at the moment.
Stewart,
Of course 5.1 will be done in some near future.
What are the chances this patch would be included in the GA 5.1 releases like the last one was I wonder? It would be a great tool to use without a patch for certain.
The log_slow_slave_statements parameter doesn’t appear in SHOW VARIABLES. It would be nice if it appeared there and was dynamically settable. Maybe I can add that to the patch if I get time.
Xaprb,
There is a new version of the patch ready, still going through some internal testing though, which allows better control over the patch work or results. But even now you could achieve the desired result by temporarily modifying global wait_timeout value and performing SLAVE STOP and SLAVE START. This will set slave thread wait_timeout as needed (e.g. 0 – log all slave queries, 100000000 – log only extremely long running queries, which practically means none).
Maciek
Maciek, I emailed Peter about this (I don’t have your email) so you may hear from him too. I altered the patch to work OK on 5.0.40 (enterprise sources, SHOW PROFILE changes makes the patch fail to apply) and built with it. I’m seeing the slave thread stop logging (though not stop executing) after a particular query. If I do a STOP SLAVE and then START SLAVE, the log starts getting written to again. Is this a known issue you are fixing with a newer version? Email me if you would like to discuss more. I can share my logs with you if you need.
Thanks!
Baron
I found out why the slave thread stops logging. For anyone else who is having the same trouble, configure log_slow_admin_statements = 1 and that will prevent it. I’m sure a future version of the patch will fix it.
Nice implementation. Sure, I will try it out
I need some help… How can I install this patch? Which file I have to patch? I have Debian etch
many thanks