Severalnines Blog
The automation and management blog for open source databases

Become a MySQL DBA blog series - Analyzing your SQL Workload using pt-query-digest

Severalnines

In our previous post, we discussed the different ways to collect data about slow queries - MySQL offers slow log, general log and binary log. Using tcpdump, you can grab network traffic data - a good and low-impact method of collecting basic metrics for slow queries. So, now that you are sitting on top of a large pile of data, perhaps tens of gigabytes of logs, how do you get a whole picture of the workload? 

Mid to large size applications tend to have hundred of SQL statements distributed throughout a large code base, with potentially hundreds of queries running every second. That can generate a lot of data. How do we identify causes of bottlenecks slowing down our applications? Obviously, going through the information query by query would not be great - we’ll get drowned with all the entries. We need to find a way to aggregate the data and make sense of all that.

One solution would be to write your own scripts to parse the logs and generate some sensible output. But why reinvent the wheel when such a script already exists, and is only a single wget away? In this blog, we’ll have a close look at pt-query-digest, which is part of Percona Toolkit.

This is the tenth installment in the ‘Become a MySQL DBA’ blog series. Our previous posts in the DBA series include Query Tuning Process, Configuration Tuning, Live Migration using MySQL Replication, Database Upgrades, Replication Topology Changes, Schema Changes, High Availability, Backup & Restore, Monitoring & Trending.

Processing data

Pt-query-digest accepts data from general log, binary log, slow log or tcpdump - this covers all of the ways MySQL can generate query data. In addition to that, it’s possible to poll the MySQL process list at a defined interval - a process which can be resource-intensive and far from ideal, but can still be used as a an alternative.

Let’s start with data collected in the slow log. For completeness we’ve used Percona Server with log_slow_verbosity=full. As a source of queries we’ve used sysbench started with --oltp-read-only=off and default query mix.

Slow log - summary part

First of all, we need to process all the data in our slow query log. This can be done by running:

$ pt-query-digest --limit=100% /var/lib/mysql/slow.log > ptqd1.out

We’ve used limit=100% to ensure all queries are included in the report, otherwise some of the less impacting queries may not end up in the output.

After a while you’ll be presented with a report file. It starts with a summary section.

# 52.5s user time, 100ms system time, 33.00M rss, 87.85M vsz
# Current date: Sat Aug 22 16:56:34 2015
# Hostname: vagrant-ubuntu-trusty-64
# Files: /var/lib/mysql/slow.log
# Overall: 187.88k total, 11 unique, 3.30k QPS, 0.73x concurrency ________
# Time range: 2015-08-22 16:54:17 to 16:55:14

At the beginning, you’ll see information about how many queries were logged, how many unique query types there were, QPS and what the concurrency looked like. You can also check the timeframe for the report.

To calculate unique queries, pt-query-digest strips down values passed in the WHERE condition, removes all whitespaces (among others) and calculates a hash for a query. Such hash, called a ‘Query ID’ is used in pt-query-digest to differentiate between queries.

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            42s     3us    66ms   221us   541us   576us   131us
# Lock time             5s       0    25ms    26us    38us   146us    21us
# Rows sent          2.78M       0     100   15.54   97.36   34.53    0.99
# Rows examine       6.38M       0     300   35.63  192.76   77.79    0.99
# Rows affecte      36.66k       0       1    0.20    0.99    0.40       0
# Bytes sent       354.43M      11  12.18k   1.93k  11.91k   4.21k  192.76
# Merge passes           0       0       0       0       0       0       0
# Tmp tables         9.17k       0       1    0.05       0    0.22       0
# Tmp disk tbl           0       0       0       0       0       0       0
# Tmp tbl size       1.11G       0 124.12k   6.20k       0  26.98k       0
# Query size        10.02M       5     245   55.95  151.03   50.65   36.69
# InnoDB:
# IO r bytes        22.53M       0  96.00k  139.75       0   1.73k       0
# IO r ops           1.41k       0       6    0.01       0    0.11       0
# IO r wait             2s       0    38ms    10us       0   382us       0
# pages distin     355.29k       0      17    2.15    4.96    2.13    1.96
# queue wait             0       0       0       0       0       0       0
# rec lock wai         2ms       0   646us       0       0     2us       0
# Boolean:
# Filesort       9% yes,  90% no
# Tmp table      4% yes,  95% no

Another part of the summary is pretty self-explanatory. This is a list of different attributes like execution time, lock time, number of rows sent, examined or modified. There’s also information about temporary tables, query size and network traffic. We also have some InnoDB metrics.

For each of those metrics you can find different statistical data. What was the total execution time (or how many rows in total were examined)? What was the minimal execution time (or minimal number of rows examined)? What was the longest query (or the most rows examined by a single query)? We have also calculated average, 95th percentile, standard deviation and median. Finally, at the end of this section you can find some information about how large percentage of queries created a temporary table or used a filesort algorithm.

Next section tells us more about each of the query type. By default pt-query-digest sorts the queries by total execution time. It can be changed, though (using --order-by flag), and you can easily sort queries by, for example, total number of rows examined.

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ==============
#    1 0x558CAEF5F387E929 14.6729 35.2% 93956 0.0002  0.00 SELECT sbtest?
#    2 0x737F39F04B198EF6  6.4087 15.4%  9388 0.0007  0.00 SELECT sbtest?
#    3 0x84D1DEE77FA8D4C3  3.8566  9.2%  9389 0.0004  0.00 SELECT sbtest?
#    4 0x3821AE1F716D5205  3.2526  7.8%  9390 0.0003  0.00 SELECT sbtest?
#    5 0x813031B8BBC3B329  3.1080  7.5%  9385 0.0003  0.00 COMMIT
#    6 0xD30AD7E3079ABCE7  2.2880  5.5%  9387 0.0002  0.00 UPDATE sbtest?
#    7 0x6EEB1BFDCCF4EBCD  2.2869  5.5%  9389 0.0002  0.00 SELECT sbtest?
#    8 0xE96B374065B13356  1.7520  4.2%  9384 0.0002  0.00 UPDATE sbtest?
#    9 0xEAB8A8A8BEEFF705  1.6490  4.0%  9386 0.0002  0.00 DELETE sbtest?
#   10 0xF1256A27240AEFC7  1.5952  3.8%  9384 0.0002  0.00 INSERT sbtest?
#   11 0x85FFF5AA78E5FF6A  0.8382  2.0%  9438 0.0001  0.00 BEGIN

As you can see, we have eleven queries listed. Each of them has a calculated summary response time and how big part of the total response time it is. We can check how many calls there were in total, what was the mean request time for a query, its variance-to-mean ratio which tells us whether the workload was stable or not. Finally, we see a query in its distilled form.

This concludes the summary part, the rest of the report discusses exact queries in more detail.

Slow log - queries

In this section pt-query-digest prints data about each of the distinct query type it determined. Queries are sorted from the most time-consuming to the least impacting one.

# Query 1: 1.65k QPS, 0.26x concurrency, ID 0x558CAEF5F387E929 at byte 46229
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2015-08-22 16:54:17 to 16:55:14
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         50   93956
# Exec time     35     15s     9us    66ms   156us   236us   713us   119us
# Lock time     52      3s       0    25ms    27us    33us   199us    20us

From the data above we can learn that this query was responsible for 35% of total execution time. It also consisted 50% of the all queries executed in this slow log. It was responsible for 52% of total row locks. We can check that the query is pretty quick - on average it took 156 microseconds to finish, the longest execution took 66 milliseconds.

# Rows sent      3  91.75k       1       1       1       1       0       1
# Rows examine   1  91.75k       1       1       1       1       0       1
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     4  17.47M     195     195     195     195       0     195
# Merge passes   0       0       0       0       0       0       0       0
# 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    32   3.27M      36      37   36.50   36.69    0.50   36.69

This query sent 3% and examined 1% of rows, which means it’s pretty well optimized when we compare that with total count (it consists 50% of all queries). It’s clearly depicted in the next columns - it scans and sends only a single row which means it is most likely either a PK or an unique key based. No temporary tables were created by this query.

# InnoDB:
# IO r bytes    46  10.42M       0  96.00k  116.31       0   1.37k       0
# IO r ops      46     667       0       6    0.01       0    0.09       0
# IO r wait     68      1s       0    38ms    12us       0   498us       0
# pages distin  14  51.33k       0       8    0.56    3.89    1.33       0
# queue wait     0       0       0       0       0       0       0       0
# rec lock wai   0       0       0       0       0       0       0       0

Next part contains InnoDB statistics. We can see that the query did some disk operations, what’s most important is the fact that it’s responsible for 68% of the InnoDB I/O wait. There are no queue waits (time spent by a thread before it could enter InnoDB kernel) or record lock waits.

# String:
# Databases    sbtest
# Hosts        10.0.0.200
# InnoDB trxID 112C (10/0%), 112D (10/0%), 112E (10/0%)... 9429 more
# Last errno   0
# Users        sbtest
# Query_time distribution
#   1us  #
#  10us  ####
# 100us  ################################################################
#   1ms  #
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `sbtest` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `sbtest`.`sbtest1`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT c FROM sbtest1 WHERE id=100790\G

Finally, we have some data covering who, where and what. What schema was used for a query? Which host executed the query. Which user executed the query? What InnoDB transaction ID’s it had? Did it end up in error? What was the error number?

We have also a nice chart covering execution time distribution - it’s very useful to locate all those queries which are “fast most of the time but sometimes not really”. These queries may suffer from internal or row level locking issues or have their execution plan flipping. Finally we have SHOW TABLE STATUS and SHOW CREATE TABLE statements printed, covering all of the tables involved in a query. It comes really handy - you can just copy it from the report and paste in the MySQL console - a very nice touch. At the end we can find a full version of the query (along with EXPLAIN, again, for easy copy/paste). Full version represents the query of a given type which had the longest execution time. For a DML, where EXPLAIN doesn’t work yet, pt-query-digest prints the equivalent written in a form of a SELECT:

UPDATE sbtest1 SET k=k+1 WHERE id=100948\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  k=k+1 from sbtest1 where  id=100948\G
ClusterControl
Single Console for Your Entire Database Infrastructure
Find out what else is new in ClusterControl

Binary log

Another example of data that pt-query-digest can process is the binary log. As we mentioned last time, binary logs contain data regarding DML’s so if you are looking for SELECTs, you won’t find them here. Still, if you are suffering from DML-related issues (significant locking for example), binary logs may be useful to, at least preliminarily, check the health of the database. What’s important is that binary logs have to be in ‘statement’ or ‘mixed’ format to be useful for pt-query-digest. If that’s the case, here are the steps you need to follow to get the report.

First, we need to parse binary logs:

$ mysqlbinlog /var/lib/mysql/binlog.000004 > binlog.000004.txt

Then we need to feed them to pt-query-digest, ensuring that we set --type flag to ‘binlog’:

$ pt-query-digest --type binlog binlog.000004.txt > ptqd_bin.out

Here’s an example output - it’s a bit messy but all data that could have been derived from the binary log is there:

# 7s user time, 40ms system time, 26.02M rss, 80.88M vsz
# Current date: Mon Aug 24 16:43:55 2015
# Hostname: vagrant-ubuntu-trusty-64
# Files: binlog.000004.txt
# Overall: 48.31k total, 9 unique, 710.44 QPS, 0.07x concurrency _________
# Time range: 2015-08-24 12:17:26 to 12:18:34
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time             5s       0      1s   103us       0    10ms       0
# Query size         4.48M       1     245   81.09  234.30   85.44   38.53
# @@session.au           1       1       1       1       1       0       1
# @@session.au           1       1       1       1       1       0       1
# @@session.au           1       1       1       1       1       0       1
# @@session.ch           8       8       8       8       8       0       8
# @@session.co           8       8       8       8       8       0       8
# @@session.co           8       8       8       8       8       0       8
# @@session.fo           1       1       1       1       1       0       1
# @@session.lc           0       0       0       0       0       0       0
# @@session.ps           2       2       2       2       2       0       2
# @@session.sq           0       0       0       0       0       0       0
# @@session.sq       1.00G   1.00G   1.00G   1.00G   1.00G       0   1.00G
# @@session.un           1       1       1       1       1       0       1
# error code             0       0       0       0       0       0       0

# Query 1: 146.39 QPS, 0.03x concurrency, ID 0xF1256A27240AEFC7 at byte 13260934
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.98
# Time range: 2015-08-24 12:17:28 to 12:18:34
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         20    9662
# Exec time     40      2s       0      1s   206us       0    14ms       0
# Query size    50   2.25M     243     245  243.99  234.30       0  234.30
# error code     0       0       0       0       0       0       0       0
# String:
# Databases    sbtest
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `sbtest` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `sbtest`.`sbtest1`\G
INSERT INTO sbtest1 (id, k, c, pad) VALUES (99143, 99786, '17998642616-46593331146-44234899131-07942028688-05655233655-90318274520-47286113949-12081567668-14603691757-62610047808', '13891459194-69192073278-13389076319-15715456628-59691839045')\G

As you can see, we have data about number of queries executed and their execution time. There’s also information about query size  and the query itself.

Tcpdump

pt-query-digest works nicely with data captured by tcpdump. We’ve discussed some ways you can collect the data in our last post. One command you may use is:

$ tcpdump -s 65535 -x -nn -q -tttt -i any port 3306 > mysql.tcp.txt

Once the capture process ends, we can proceed with processing the data:

$ pt-query-digest --limit=100% --type tcpdump mysql.tcp.txt > ptqd_tcp.out

Let’s take a look at the final report:

# 113s user time, 3.4s system time, 41.98M rss, 96.71M vsz
# Current date: Mon Aug 24 18:23:20 2015
# Hostname: vagrant-ubuntu-trusty-64
# Files: mysql.tcp.txt
# Overall: 124.42k total, 12 unique, 1.98k QPS, 0.95x concurrency ________
# Time range: 2015-08-24 18:15:58.272774 to 18:17:00.971587
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            59s       0   562ms   477us     2ms     3ms   152us
# Rows affecte      24.24k       0       1    0.20    0.99    0.40       0
# Query size         6.64M       5     245   55.97  151.03   50.67   36.69
# Warning coun           0       0       0       0       0       0       0

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ==============
#    1 0x558CAEF5F387E929 18.1745 30.6% 62212 0.0003  0.01 SELECT sbtest?
#    2 0x813031B8BBC3B329  8.9132 15.0%  6220 0.0014  0.09 COMMIT
#    3 0x737F39F04B198EF6  6.8068 11.4%  6220 0.0011  0.00 SELECT sbtest?
#    4 0xD30AD7E3079ABCE7  5.0876  8.6%  6220 0.0008  0.00 UPDATE sbtest?
#    5 0x84D1DEE77FA8D4C3  3.7781  6.4%  6220 0.0006  0.00 SELECT sbtest?
#    6 0xE96B374065B13356  3.5256  5.9%  6220 0.0006  0.00 UPDATE sbtest?
#    7 0x6EEB1BFDCCF4EBCD  3.4662  5.8%  6220 0.0006  0.00 SELECT sbtest?
#    8 0xEAB8A8A8BEEFF705  2.9711  5.0%  6220 0.0005  0.00 DELETE sbtest?
#    9 0xF1256A27240AEFC7  2.9067  4.9%  6220 0.0005  0.00 INSERT sbtest?
#   10 0x3821AE1F716D5205  2.6769  4.5%  6220 0.0004  0.00 SELECT sbtest?
#   11 0x85FFF5AA78E5FF6A  1.1544  1.9%  6222 0.0002  0.00 BEGIN
#   12 0x5D51E5F01B88B79E  0.0030  0.0%     2 0.0015  0.00 ADMIN CONNECT
# Query 1: 992.25 QPS, 0.29x concurrency, ID 0x558CAEF5F387E929 at byte 293768777
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2015-08-24 18:15:58.273745 to 18:17:00.971587
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         50   62212
# Exec time     30     18s       0   448ms   292us   657us     2ms   113us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size    32   2.17M      36      37   36.50   36.69    0.50   36.69
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    sbtest^@mysql_native_password
# Hosts        10.0.0.200
# Users        sbtest
# Query_time distribution
#   1us  #
#  10us  ########################
# 100us  ################################################################
#   1ms  ###
#  10ms  #
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `sbtest^@mysql_native_password` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `sbtest^@mysql_native_password`.`sbtest1`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT c FROM sbtest1 WHERE id=138338\G

It looks fairly similar to the report generated from binary logs. What’s important - resolution is much better. Binary log could show us query execution time rounded to the nearest second, here we enjoy the same resolution as when using slow log with long_query_time=0.

Unfortunately, we are missing every single additional information that slow log could provide - only query count, query execution time and query size is there. Better resolution, though, allows the query execution time graph to be more detailed and therefore it can be used to quickly check if a given query has stable performance or not.

In the previous blog post we mentioned that it’s common to combine different methods of gathering information about queries in the system. We hope you see now why - if you need detailed data, there’s no other way than to use the slow query log. For a day-to-day checks it’s enough to use TCP traffic - it’s less impacting than logging all queries to the slow log, it’s also good enough for determining if a query suffers from slowdowns or not.

In the next post we will walk you through some examples of pt-query-digest reports and how we can derive important information out of them. We will also show you how you can benefit from a different additional options that pt-query-digest offers to get more detailed information.