arrow-down coffee engineering consultancy development remote-management support linkedin twitter youtube email phone

analysing slow MySQL queries with pt-query-digest

Submitted by Krishna Prajapati on September 08, 2014

pt-query-digest is a tool available from Percona for analysis of MySQL queries from slow log, general log and binary log files. It can also analyze queries from mysql processlist and tcpdump mysql data. It is one of the best tools for slow query analysis on mysql server and can help you to improve mysql performance and efficiency. This tool is part of Percona Toolkit, the well-known MySQL management software utility toolkit for MySQL server administration (of course it also works on MariaDB and Percona Server). Formerly, percona toolkit was known as maatkit and pt-query-digest was called mk-query-digest. It has lots of options available to explore. In this post we'll compare some of the different sources pt-query-digest can use.

Slow query logs

MySQL can log queries which take longer then a specified time to execute into a separate log file. Some queries take longer because of issues on the application side, some because of bad schema design. The slow query log can help you to find those queries and make it easy to debug your application. The problem is that the slow query log by default is just a long list of queries that took longer then a certain amount of time. Pt-query-digest can take a slow query log file and summarize it smartly so that you get to see how many and which type of query are causing trouble. Slow query options should be enabled in MySQL for debugging purpose only. Disable them once you are done with your analysis.

Enabling Slow query

You can enable slow query by adding the following into mysql config file.

slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 2
log_queries_not_using_indexes

The last line tells mysql to log queries that are not using any indexes regardless of how long they take. You can keep this commented if you want to ignore those kinds of queries.

Here's how you can dynamically enable the slow query log without a mysql-server restart:

set global slow_query_log = 1;
set global slow_query_log_file = '/var/log/mysql/mysql-slow.log';
set global long_query_time = 2;
set global log_queries_not_using_indexes=1;

pt-query-digest with mysql slow.log

The basic usage is below.

root@krishna:~# pt-query-digest /var/log/mysql/mysql-slow.log

The result set looks like below.

# 560ms user time, 30ms system time, 19.48M rss, 25.68M vsz
# Current date: Thu Jul 24 10:14:45 2014
# Hostname: krishna
# Files: ksslow.log
# Rate limits apply
# Overall: 77 total, 15 unique, 0.03 QPS, 1.21x concurrency ______________
# Time range: 2014-07-23 10:49:34 to 11:33:18
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3182s 63ms 865s 41s 40s 153s 10s
# Lock time 35ms 0 4ms 459us 1ms 639us 185us
# Rows sent 56.04k 0 27.50k 745.21 102.22 4.34k 0.99
# Rows examine 649.91M 133.27k 171.03M 8.44M 9.30M 31.79M 535.27k
# Rows affecte 0 0 0 0 0 0 0
# Bytes sent 17.59M 52 7.18M 233.96k 33.17k 1.13M 1.04k
# Merge passes 0 0 0 0 0 0 0
# Tmp tables 38 0 4 0.49 0.99 0.77 0
# Tmp disk tbl 2 0 1 0.03 0 0.16 0
# Tmp tbl size 531.08M 0 71.99M 6.90M 62.35M 17.41M 0
# Query size 214.90k 29 14.18k 2.79k 6.01k 3.17k 537.02
# InnoDB:
# IO r bytes 4.41M 0 4.41M 58.60k 0 493.89k 0
# IO r ops 282 0 282 3.66 0 30.71 0
# IO r wait 707ms 0 707ms 9ms 0 80ms 0
# pages distin 1.39M 575 51.93k 18.52k 44.45k 19.63k 833.10
# queue wait 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0
# Boolean: # Filesort 36% yes, 63% no
# Full join 19% yes, 80% no
# Full scan 57% yes, 42% no
# Tmp table 38% yes, 61% no
# Tmp table on 2% yes, 97% no
.....
.....
# Query 2: 0.01 QPS, 0.10x concurrency, ID 0x3B88951029FF7EF4 at byte 62669
# Scores: V/M = 0.54
# Time range: 2014-07-23 10:51:18 to 11:33:10
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 19 15
# Exec time 7 240s 11s 22s 16s 19s 3s 15s
# Lock time 6 2ms 107us 265us 161us 194us 34us 152us
# Rows sent 0 17 0 3 1.13 1.96 0.78 0.99
# Rows examine 6 42.31M 2.82M 2.82M 2.82M 2.75M 0 2.75M
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 0 1.61k 96 132 109.60 118.34 10.10 107.34
# Merge passes 0 0 0 0 0 0 0 0
# Tmp tables 39 15 1 1 1 1 0 1
# Tmp disk tbl 0 0 0 0 0 0 0 0
# Tmp tbl size 18 95.95M 0 8.00M 6.40M 7.65M 3.06M 7.65M
# Query size 3 8.19k 559 559 559 559 0 559
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0 0
# IO r ops 0 0 0 0 0 0 0 0
# IO r wait 0 0 0 0 0 0 0 0
# pages distin 43 618.42k 41.22k 41.24k 41.23k 40.32k 0 40.32k
# queue wait 0 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0 0
# Boolean:
# Filesort 100% yes, 0% no
# Full join 100% yes, 0% no
# Tmp table 100% yes, 0% no
..........
..........

pt-query-digest with processlist

The result set of processlist is similar to the above result set. Basically, it analyzes the processlist, the currently running/coming up queries by simply parsing the result of show full processlist. The problem is that show full processlist only shows queries that are executing the moment the command is run, so it is hard to catch fast queries this way. Therefore, this option is suitable for catching very long running queries.


root@krishna:~# pt-query-digest --processlist h=host,user=user,password=pass --output=slow.log

pt-query digest with tcpdump:

tcpdump is a packet analyzer. It allows the user to intercept tcp/ip packet over the network. Decodes mysql client protocol, extract queries and responses. pt-query-digest parse the output file from tcpdump. The parser expects the input to be formatted with the following options: -x -n -q -tttt.

The advantage is that this catches every query that is executed as it analyzes raw tcp traffic. The disadvantage is that TCP dump files can grow in size very quickly.


root@krishna:~# tcpdump -s 65535 -x -nn -q -tttt -i any -c 50000 port 3306 > mysqltcp.txt
root@krishna:~# pt-query-digest --type tcpdump mysqltcp.txt

Resultset:


# 356.4s user time, 3.5s system time, 97.97M rss, 165.85M vsz
# Current date: Wed Jul 23 11:58:39 2014
# Hostname: krishna
# Files: mysqltcp.txt
# Overall: 352.25k total, 1.34k unique, 2.95k QPS, 19.03x concurrency ____
# Time range: 2014-07-23 11:44:46.232162 to 11:46:45.753707
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          2274s       0     24s     6ms    13ms   104ms   332us
# Rows affecte       5.00k       0     143    0.01       0    0.41       0
# Query size        68.95M       6  22.05k  205.24  592.07  338.35  118.34
# Warning coun      21.21k       0  12.30k    0.06       0   25.20       0
# Boolean:
# No index use   6% yes,  93% no

# Profile
# Rank Query ID           Response time   Calls  R/Call  V/M   Item
# ==== ================== =============== ====== ======= ===== ===========
#    1 0x95A1CC500FC29F21 1008.2648 44.3%  14121  0.0714  0.15 SELECT
#    2 0x11A9AF509407F4A9  146.5381  6.4%   1897  0.0772  0.04 CALL supfeast
#    3 0x04FE01C5B31FD305   89.2830  3.9%  17815  0.0050  4.28 ADMIN PING
#    4 0x294AEAFA12D97288   84.0566  3.7%    147  0.5718  2.41 SELECT api_rdesis_log
#    5 0xFF59A07A4F0E387A   66.5984  2.9%  18799  0.0035  9.95 ADMIN INIT_DTYUB
#    6 0x4FDE082D7D9AD791   45.5026  2.0%    264  0.1724  1.70 SELECT user customers
#    7 0xE19C63D1ED311D2F   42.4127  1.9%      5  8.4825  0.02 UPDATE apiq
#    8 0x321C2E6675AD6BD8   34.9162  1.5%   2187  0.0160  0.71 SELECT instde_text
#    9 0x6A227977E7A1A853   32.6140  1.4%  16630  0.0020  0.00 SELECT
#   10 0x33039CDA0AE0C7B9   30.3050  1.3%   3406  0.0089  0.63 SELECT
#   11 0x2AA0A56D9D98864A   29.3268  1.3%  12422  0.0024  5.26 SELECT promot
......
# Query 1: 118.16 QPS, 8.44x concurrency, ID 0x95A1CC500FC29F21 at byte 1493651156
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.15
# Time range: 2014-07-23 11:44:46.246615 to 11:46:45.751127
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4   14121
# Exec time     44   1008s     6ms      5s    71ms   230ms   104ms    36ms
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     5   3.72M     271     278  276.02  271.23    1.17  271.23
# Warning coun   0       0       0       0       0       0       0       0
# Boolean:
# No index use  99% yes,   0% no
# String:
# Hosts        192.168.100.77
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ########################
#  10ms  ################################################################
# 100ms  ################################
#    1s  #
#  10s+
......
.......

Conclusion:

The pt-query-digest was once started as a very simple slow query log analysis tool, but has over time become a very versatile tool to do one of the things so many people want: catch their slowest running queries so they can be improved.

If you like pt-query-digest, have a look at anemometer http://olindata.com/blog/2014/07/anemometer-mysql-slow-query-monitor as "a picture is worth a thousand words".  This tool too uses pt-query-digest.