You are here

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

MySQL Performance Blog - Thu, 01/11/2007 - 12:40am

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.

PLAIN TEXT CODE:
  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 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 long_query_time is in microseconds and you can set it for example to 300000 which is 0.3s!

PLAIN TEXT CODE:
  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 --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.

PLAIN TEXT CODE:
  1. # QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: Yes  Disk_tmp_table: No
  2. # Filesort: Yes  Disk_filesort: No  Merge_passes: 0

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 Full_scan is set then most likely the query is a bad one, because it read all the rows from a table.

Full_join means any of the joins didn’t use indexes.

If a temporary table is required for query execution Tmp_table will be set. Sometimes that table must be created on disk instead of in memory, in such case Disk_tmp_table will state that.

Filesort is for indicating that filesort algorithm was used, while 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 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.

PLAIN TEXT CODE:
  1. #   InnoDB_IO_r_ops: 19  InnoDB_IO_r_bytes: 311296  InnoDB_IO_r_wait: 0.382176
  2. #   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.067538
  3. #   InnoDB_pages_distinct: 20

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. InnoDB_IO_r_bytes is the corresponding value in bytes.

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

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

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

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 would take a lot of memory to map all the pages. The inaccuracy grows with the number of pages accessed by a query.

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:

PLAIN TEXT CODE:
  1. # User@Host: macko[macko] @ localhost []
  2. # Thread_id: 4
  3. # Query_time: 0.503016  Lock_time: 0.000048  Rows_sent: 56  Rows_examined: 1113
  4. # QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: Yes  Disk_tmp_table: No
  5. # Filesort: Yes  Disk_filesort: No  Merge_passes: 0
  6. #   InnoDB_IO_r_ops: 19  InnoDB_IO_r_bytes: 311296  InnoDB_IO_r_wait: 0.382176
  7. #   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.067538
  8. #   InnoDB_pages_distinct: 20
  9. SET timestamp=1193841780;
  10. SELECT DISTINCT c from sbtest where id between 501895 and 502895 order by c;

or if InnoDB was not used:

PLAIN TEXT CODE:
  1. # Time: 071031 20:03:16 # User@Host: macko[macko] @ localhost []
  2. # Thread_id: 12
  3. # Query_time: 0.026385  Lock_time: 0.000158  Rows_sent: 1  Rows_examined: 0
  4. # QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: No  Disk_tmp_table: No
  5. # Filesort: No  Disk_filesort: No  Merge_passes: 0
  6. # No InnoDB statistics available for this query
  7. 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 download for MySQL Community 5.0.45.

Maciek Dobrzański

Entry posted by maciek | No comment

Add to: delicious | digg | reddit | netscape | Google Bookmarks