How to read a slow query digest

Slow queries

After you have a slow query digest (as discussed in Tools for parsing a slow query log), you can begin to evaluate where problems might be occurring.

Information about the log

The first part of a slow query log is the digest information.


# 1.6s user time, 20ms system time, 32.08M rss, 61.39M vsz
# Current date: Tue Aug  7 13:10:57 2012
# Hostname: staging-1047.prod.hosting.acquia.com
# Files: mysqld-slow.log
# Overall: 3.16k total, 404 unique, 0.14 QPS, 0.80x concurrency __________
# Attribute          total     min     max     avg     95%  stddev  median
# =========        ======= ======= ======= ======= ======= ======= =======
# Exec time         18105s      1s    935s      6s     12s     28s      2s
# Lock time            29s       0      2s     9ms     4ms    67ms       0
# Rows sent         62.37M       0   6.03M  20.19k  33.17k 196.65k    0.99
# Rows exam         73.95M       0   6.03M  23.94k  92.42k 197.17k    0.99
# Time range        2012-08-07 06:47:17 to 2012-08-07 13:05:53
# bytes              3.54M      11   1.30M   1.15k  537.02  32.70k   88.31
# Rows affe         89.04k       0   3.11k   28.83    0.99  250.23       0
# Rows read         75.64M       0   6.03M  24.49k  97.04k 198.56k    0.99

The log includes the following items (with specific references from the example):

  • When was it run? Tue Aug 7 13:10:57 2012
  • On what hostname? staging-1047.prod.hosting.acquia.com
  • How many lines were processed? 3.16k total, 404 unique

Identifying problems

The next section provides an overview of what queries were the slowest. They're ranked in descending order, with the worst offender having a Rank of 1:


# Profile
# Rank Query ID           Response time    Calls R/Call   Item
# ==== ================== ================ ===== ======== ================
#    1 0x67A347A2812914DF  3689.6381 20.4%   351  10.5118 SELECT watchdog
#    2 0x2FA97A9508A98849  3337.4335 18.4%    18 185.4130 SELECT watchdog
#    3 0x13071EB1C98EA90B  1356.7068  7.5%    58  23.3915 SELECT variable
#    4 0x30FE5C2032672827  1093.2228  6.0%   804   1.3597 SHOW TABLE STATUS
#    5 0x748DEEF28EA5992D   952.6171  5.3%     8 119.0771 DELETE cache_fpe
#    6 0xF080ABC5341CBEE1   320.7495  1.8%    81   3.9599 UPDATE apachesolr_index_entities_node taxonomy_index
#    7 0x7AF789F9862CBC08   301.1504  1.7%    40   7.5288 SELECT search_total search_index
#    8 0x6BCD96962189B14D   261.2722  1.4%    22  11.8760 SELECT apachesolr_search_node node
#    9 0xCE1FFB25CB1ACF8E   191.9873  1.1%    47   4.0848 SELECT cache_bootstrap
#   10 0xD92183ACD7A21D6A   185.5956  1.0%    43   4.3162 SELECT field_data_body

The remaining column headers are described as follows:

  • Query ID - A hash of the query. You're not likely to need this.
  • Response time - The average amount of time needed to execute this query.
  • Calls - What percentage of the slow query log is this query?
  • R/Call - The mean response time per execution.
  • Item - A truncated version of the query.

From this, you can determine that watchdog queries occupy the two top slots, accounting for nearly 40% of of the calls to the database.

In-depth analysis

After the overview, the script provides an in-depth detail section about each query. Some of it is of interest, while other sections may be less useful. Let's look at the #2 ranked query from the previous section. Because of the amount of output for this section, we'll break it into sections:

Runtime statistics

One of the first lines in this section provides the column headers for the query's table of information. Pay attention to the following columns:

  • pct (Percentage) - The percent of the total for the whole analysis run.
  • total - The actual value of the specified metric.
  • 95% - The 95th percentile; 95% of the values are less than or equal to this value.
  • stddev (Standard deviation) - How tightly grouped the values are.

The standard deviation and median are both calculated from the 95th percentile, discarding the extremely large values.


# Query 2: 0.00 QPS, 0.15x concurrency, ID 0x2FA97A9508A98849 at byte 1909177
# This item is included in the report because it matches --limit.
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ========= ====== ======= ======= ======= ======= ======= ======= =======
# Count          0      18
# Exec time     18   3337s      1s    652s    185s    314s    145s    167s
# Lock time      0    56ms       0    56ms     3ms       0    13ms       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      1   1.34M    1003  97.67k  76.19k  97.04k  39.91k  97.04k

You can also examine Rows sent/Rows exam (examined) as an indicator of query problems. These numbers should ideally be nearly a 1:1 ratio. A large number of rows examined, but a small number of rows sent, means that the query is examining much more data than it's returning — this may mean the query is inefficient. Indexing may help with queries like this.

Users, databases, and time range

The next section displays statistics regarding the users, databases, and time range for the query. The users and databases are displayed as a count of distinct values, followed by the values. If there's only one, it's displayed alone; if there are many, the section displays each of the most frequent ones, followed by the number of times that it appears:


# Users                  3 website1... (14/77%), websitestg (3/16%)... 1 more
# Hosts                  1 staging-1047.prod.hosting.acquia.com
# Databases              6 website1add... (7/38%), website1add... (7/38%)... 4 more
# Time range 2012-08-07 07:03:41 to 2012-08-07 13:05:51
# bytes          0   6.82k     388     388     388     388       0     388
# Rows affe      0       0       0       0       0       0       0       0
# Rows read      0       0       0       0       0       0       0       0

Visual breakdown of execution time

The log then displays a graph that provides a visual breakdown of the amount of time this query typically needed to complete. This query sometimes only needed approximately one second to run, but generally needed over 10 seconds to complete. The one second benchmark is where Acquia Support generally starts looking for issues with queries, as these can start having performance impacts.


# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ##################
#  10s+  ################################################################

Query review

Finally, the log includes the query that was problematic. The \G flag at the end is an instruction to format the query across multiple lines for easier reading. The lines beginning with # are comments, and are not part of the query being examined.

Here's how an example query would be presented:


# Tables
#    SHOW TABLE STATUS FROM `website1addb2886` LIKE 'watchdog'\G
#    SHOW CREATE TABLE `website1addb2886`.`watchdog`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT w.message AS message, w.variables AS variables
FROM 
watchdog w
WHERE  (w.message LIKE 'login attempty failed%' ESCAPE '\\') AND (w.timestamp > '1344294002') 
AND (w.message NOT IN  ('UPGRADE.txt', 'MAINTAINERS.txt',  'README.txt', 'INSTALL.pgsql.txt', 
'INSTALL.txt', 'LICENSE.txt', 'INSTALL.mysql.txt', 'COPYRIGHT.txt', 'CHANGELOG.txt'))  
ORDER BY w.timestamp DESC
LIMIT 10 OFFSET 0\G

Slow queries grouped by database

You can also use pt-query-digest to provide output that is grouped by database.

pt-query-digest --limit 100% --group-by db slow.log > slow-db.txt

This returns information similar to what's been previously described on this page, with an added Item field that identifies the database.


# Profile
# Rank Query ID Response time      Calls  R/Call   Item
# ==== ======== ================== ====== ======== ===============
#    1 0x       2128815.3618 76.9% 161869  13.1515 db1
#    2 0x        289770.3525 10.5%  10281  28.1850 db2
#    3 0x        156921.2035  5.7%   5567  28.1877 db3
#    4 0x         50476.0517  1.8%   1151  43.8541 db4

Contact supportStill need assistance? Contact Acquia Support