Profiling your slow queries using pt-query-digest and some love from Percona Server

Overview

Profiling, analyzing and then fixing slow queries is likely the most oft-repeated part of a job of a DBA. And there are not too many tools out there that can make your life easy by providing analysis of queries with such data points that allow you to attack the right queries in the right way. One such tool that I have always found myself using is pt-query-digest(formerly known as mk-query-digest).

Now let us go through using this very nice tool.

Before We Start!

But before we start, make sure you have enabled slow query logging and set a low enough long_query_time. The correct value of long_query_time depends on your application requirements, a long_query_time of 1 second or 2 seconds might be sufficient for most of the users. Its also typical to see in many cases that you set the long_query_time to 0 for a small period of time to log all the queries.

Note that logging all queries in this fashion as opposed to the general query log, enables us to have the statistics available after the query is actually executed, while no such statistics are available for queries that are logged using the general query log.

And there might be other cases when you want to log queries taking less than 1 second of time(micro-seconds), for that you can specify a value in fractions, for example, you can specify long_query_time=0.5 to log queries taking greater than half-a-second.

Note that logging queries taking fraction of a second is not possible for versions of MySQL < 5.1, unless you use the microslow patch developed by Percona. You can follow the guide here if you are still running MySQL < 5.1 and would like to install this patch. You should also note that for versions of MySQL < 5.1 setting long_query_time=0 would actually disable the slow query logging.

Installing pt-query-digest tool (as well as other tools from Percona Toolkit) is very easy, and is explained here at this link.

Using pt-query-digest

Using pt-query-digest is pretty straight forward:

pt-query-digest /path/to/slow-query.log

Note that executing pt-query-digest can be pretty CPU and memory consuming, so ideally you should download the "slow query log" to another machine and run it there.

Analyzing pt-query-digest Output

Now let's see what output it returns. The first part of the output is an overall summary:

# 250ms user time, 20ms system time, 17.38M rss, 53.62M vsz
# Current date: Wed Dec 28 08:16:13 2011
# Hostname: somehost.net
# Files: ./slow-query.log
# Overall: 296 total, 12 unique, 0.00 QPS, 0.00x concurrency _____________
# Time range: 2011-11-26 17:44:58 to 2011-12-27 13:01:44
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           736s      1s     23s      2s      6s      2s      1s
# Lock time            5ms       0   290us    17us   103us    43us       0
# Rows sent          8.31M       0   8.31M  28.75k  202.40 477.30k       0
# Rows examine      53.69k       0   3.51k  185.75  964.41  497.06       0
# Rows affecte          38       0       1    0.13    0.99    0.33       0
# Rows read          8.31M       0   8.31M  28.75k  202.40 477.30k       0
# Bytes sent       294.94M       0 275.07M 1020.33k  79.83k  15.63M  79.83k
# Tmp tables            16       0       4    0.05       0    0.45       0
# Tmp disk tbl           0       0       0       0       0       0       0
# Tmp tbl size       1.94M       0 496.08k   6.70k       0  56.06k       0
# Query size        36.89k      44     886  127.63  420.77  144.69   69.19

It tells you that there are a total of 296 slow queries which are actually invocations of 12 different queries. Following that there are summaries of various other data points such as the total query execution time and the average query execution time. One thing I suggest here is that, you should probably give more importance to the times/values reported in the 95% (95th percentile) column as that gives us more accurate understanding. Now, for example, from this summary you can easily see whether you need to bump up the tmp_table_size variable if you see a big "Tmp disk tbl" number, you can easily adjust the value of tmp_table_size by taking a look at the 95% column for the row dealing with "Tmp tbl size". Pretty nifty!

Let's analyze next part of the output produced by pt-query-digest.

# Profile
# Rank Query ID           Response time  Calls R/Call  Apdx V/M   Item
# ==== ================== ============== ===== ======= ==== ===== ========
#    1 0x92F3B1B361FB0E5B 644.9895 87.6%   244  2.6434 0.44  1.26 SELECT wp_options
#    2 0x555191621979A464  33.6349  4.6%    30  1.1212 0.65  0.03 REPLACE SELECT test.checksum test.sbtest_myisam
#    3 0x8354260420CBD34B  22.6124  3.1%     1 22.6124 0.00  0.00 SELECT customer address category

The above part of the output ranks the queries and shows the top slowest queries. As we can see here the slowest one is the SELECT wp_options, this is basically a unique way of identifying the query and simply implies that this is a SELECT query executed against the wp_options table.

Now let's take a look at the most important part of the output:

# Query 1: 0.00 QPS, 0.00x concurrency, ID 0x92F3B1B361FB0E5B at byte 119442
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.44 [1.0], V/M = 1.26
# Query_time sparkline: |      ^ |
# Time range: 2011-12-08 17:48:20 to 2011-12-27 13:01:44
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         82     244
# Exec time     87    645s      1s     10s      3s      6s      2s      1s
# Lock time     37     2ms       0   201us     8us    60us    30us       0
# Rows sent      0   3.40k       0     211   14.28  202.40   51.53       0
# Rows examine   7   4.01k       0     252   16.84  234.30   60.55       0
# Rows affecte   0       0       0       0       0       0       0       0
# Rows read      0   3.40k       0     211   14.28  202.40   51.53       0
# Bytes sent     6  19.03M  41.35k  83.95k  79.88k  79.83k   6.92k  79.83k
# Tmp tables     0       0       0       0       0       0       0       0
# Tmp disk tbl   0       0       0       0       0       0       0       0
# Tmp tbl size   0       0       0       0       0       0       0       0
# Query size    45  16.92k      71      71      71      71       0      71
# String:
# Databases    wp_blog_one (154/63%), wp_blog_tw... (81/33%)... 1 more
# Hosts
# InnoDB trxID 7F1910 (1/0%), 7F3860 (1/0%), 7F9F74 (1/0%)... 14 more
# Last errno   0
# Users        wp_blog_one (154/63%), wp_blog_two (81/33%)... 1 more
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `wp_blog_two` LIKE 'wp_options'\G
#    SHOW CREATE TABLE `wp_blog_two`.`wp_options`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes'\G

This is the actual part of the output dealing with analysis of the most slowest query ranked #1. The first row in the table above shows the Count of number of times this query was executed. Now let's take a look at the values in the 95% column, we can clearly see that this query is taking up a lot of execution time (6s) and is sending a lot of rows (202) and a lot of data (79.83k). The "Databases" section of the output also shows the name of the databases where this query was executed. Next the "Query_time distribution" section shows how this query times, which you can see lies in the range 1s to 10s all the time. The "Tables" section lists the queries that you can use to gather more data about the underlying tables involved and the query execution plan used by MySQL.
The end result might be that you end up limiting the number of results returned by the query, by using a LIMIT clause or by filtering based on the option_name column.

Let's analyze another slow query, this time query ranked #3 by pt-query-digest.

# Query 3: 0 QPS, 0x concurrency, ID 0x8354260420CBD34B at byte 132619 ___
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.00 [1.0]*, V/M = 0.00
# Query_time sparkline: |       ^|
# Time range: all events occurred at 2011-12-23 17:07:16
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       1
# Exec time      3     23s     23s     23s     23s     23s       0     23s
# Lock time      1   101us   101us   101us   101us   101us       0   101us
# Rows sent     99   8.31M   8.31M   8.31M   8.31M   8.31M       0   8.31M
# Rows examine   0      24      24      24      24      24       0      24
# Rows affecte   0       0       0       0       0       0       0       0
# Rows read     99   8.31M   8.31M   8.31M   8.31M   8.31M       0   8.31M
# Bytes sent    93 275.07M 275.07M 275.07M 275.07M 275.07M       0 275.07M
# Tmp tables     0       0       0       0       0       0       0       0
# Tmp disk tbl   0       0       0       0       0       0       0       0
# Tmp tbl size   0       0       0       0       0       0       0       0
# Query size     0      92      92      92      92      92       0      92
# String:
# Databases    another_db
# Hosts
# InnoDB trxID 83E808
# Last errno   0
# Users        another_db
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `another_db` LIKE 'customer'\G
#    SHOW CREATE TABLE `another_db`.`customer`\G
#    SHOW TABLE STATUS FROM `another_db` LIKE 'address'\G
#    SHOW CREATE TABLE `another_db`.`address`\G
#    SHOW TABLE STATUS FROM `another_db` LIKE 'category'\G
#    SHOW CREATE TABLE `another_db`.`category`\G
# EXPLAIN /*!50100 PARTITIONS*/
select customer.store_id, address.address, category.name
  from customer, address, category\G

Let's again take a look at the 95% column in the above output. And you can clearly see that the problem with this query is that its reading and sending far too many rows (8.31M) and sending far too much data (275M). Going down quickly to the "Tables" section, you can see why that is happening: "Three tables joined without a join condition meaning a cartesian product of all the rows in all the three tables". See how easily you could pin-point the cause of slowness.
This query was actually executed on a demo of a MySQL Web Client running on one of the MySQL servers managed by me, providing me with good reason to turn on safe-updates option.

Gather Even More Stats with some extra love from Percona Server!

My colleagues at Percona have built in much more verbosity to what is output in the slow query log, which would give you even more insight into what is actually going on behind the scene during the execution of a particular slow query. This is through the edition of a new variable available in Percona Server 5.1 and above called log_slow_verbosity. You can read more about this variable and some other diagnostics added to the Percona server from this link. The variable log_slow_verbosity can have the values 'microtime', 'query_plan', 'innodb' and 'full'. Let's turn on log_slow_verbosity as follows:

set session log_slow_verbosity='microtime,query_plan,innodb';

And see how verbose the new entry in slow log is:

# Time: 111228 11:52:30
# User@Host: root[root] @ localhost []
# Thread_id: 57  Schema: mywebsql_demo  Last_errno: 0  Killed: 0
# Query_time: 204.981516  Lock_time: 0.000133  Rows_sent: 10000  Rows_examined: 8721904  Rows_affected: 0  Rows_read: 10000
# Bytes_sent: 164952  Tmp_tables: 2  Tmp_disk_tables: 1  Tmp_table_sizes: 1995142008
# InnoDB_trx_id: 856C30
# QC_Hit: No  Full_scan: Yes  Full_join: Yes  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 662
#   InnoDB_IO_r_ops: 1  InnoDB_IO_r_bytes: 16384  InnoDB_IO_r_wait: 0.034391
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 11
SET timestamp=1325073150;
select customer.store_id, address.address, category.name   from customer, address, (select * from category) as category order by customer.store_id limit 10000;

See how much more information the slow query log has now, it reports everything from InnoDB stats to on disk filesort was needed for the query, etc. Now you can clearly see this is much much more helpful then the regular slow query statistics reported by the vanilla MySQL.

Conclusion

The only conclusion, I can make out is "Get yourself Percona Server, turn on log_slow_verbosity and start using pt-query-digest", your job of identifying bottleneck queries will be all the more simpler then.

  • http://www.pythian.com/news/29775/log-buffer-252-a-carnival-of-the-vanities-for-dbas/ Log Buffer #252, A Carnival of the Vanities for DBAs | The Pythian Blog

    [...] Ovais Tariq has a guide which will get you up and running with how to identify the bottleneck queries using the excellent tool pt-query-digest, and much more. [...]

  • Oakley vault

    The eyewear brand companies Oakley vault sunglasses mainly for women with a couple of designs in the actual mens category. Known because of its colorful and unique sets, Oakley vault are easily recognizable using the embossed logo on the actual temples. The exquisite design is from the frames range from Oakley sunglasses outlet to classic aviator tones, with pastel and earthy colored lenses. The variety of colors the brand offers could be compared with the mood from the Cheap Oakley vault.

blog comments powered by Disqus