blog
Analyzing Your SQL Workload Using pt-query-digest
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, 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.outWe’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:14At 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% noAnother 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 BEGINAs 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 20usFrom 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.69This 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 0Next 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=100790GFinally, 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=100948G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select k=k+1 from sbtest1 where id=100948GBinary 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.txtThen 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.outHere’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')GAs 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.txtOnce the capture process ends, we can proceed with processing the data:
$ pt-query-digest --limit=100% --type tcpdump mysql.tcp.txt > ptqd_tcp.outLet’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=138338GIt 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.
