July 23, 2014

The new cool MySQL patch has landed! Check your queries performance!

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.

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

value as seconds. In effect one could only choose to log all queries to see those which take less than 1s. Now

is in microseconds and you can set it for example to 300000 which is 0.3s!

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

.

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.

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

is set then most likely the query is a bad one, because it read all the rows from a table.

means any of the joins didn’t use indexes.

If a temporary table is required for query execution

will be set. Sometimes that table must be created on disk instead of in memory, in such case

will state that.

is for indicating that filesort algorithm was used, while

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

, 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.

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.

is the corresponding value in bytes.

With

you can see how much time (in seconds) it took InnoDB to actually read the data from storage.

is the time (in seconds) query had to wait on row locks.

is the time (in seconds) query spent either waiting to enter the InnoDB queue or inside that queue waiting for execution.

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:

or if InnoDB was not used:

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

About Maciej Dobrzanski

Maciek is a former Percona employee.
An IT consultant with the primary focus on systems, databases and application stacks performance and scalability. Expert on open source technologies such as Linux, BSD, Apache, nginx, MySQL, and many more. Co-author of dba square - a blog about how to manage, scale, and optimize MySQL performance!

Comments

  1. Great. I can’t wait to try out the InnoDB IO stats.

  2. Amy Lin says:

    We are using now !!

  3. Good patch! A lot of usefull information…

    What about backport for MySQL 4.1 ?

  4. 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)

  5. Maciej Dobrzanski says:

    Michael,

    The backport to 4.1 may happen, although this is uncertain at the moment.

  6. Maciej Dobrzanski says:

    Stewart,

    Of course 5.1 will be done in some near future.

  7. 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.

  8. Xaprb says:

    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.

  9. Maciej Dobrzanski says:

    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

  10. Xaprb says:

    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

  11. Xaprb says:

    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.

  12. Nice implementation. Sure, I will try it out

  13. mrazicek says:

    I need some help… How can I install this patch? Which file I have to patch? I have Debian etch

    many thanks

Speak Your Mind

*