Troubleshooting MySQL Slow Queries with Tcpdumps

What Is A Tcpdump?

Tcpdump is a Linux command for watching a network interface, and displaying traffic that moves across it.  

On my Mac, the airport network interface (en1) is my main connection to the internet.  You may well want to use eth0 there.  So, I can do some packet sniffing with tcpdump as follows:

$ tcpdump -i en1

Now tell tcpdump you want the whole packet:

$ tcpdump -i en1 -s 65535

And lastly return the packet as hex:

$ tcpdump -i en1 -s 65535 -x

We can see that tcpdump is exposing the contents of packets across a network interface.  Now it turns out that MySQL runs on a server at port 3306 to handle incoming connections.  Here is how we'd invoke tcpdump to watch MySQL:

$ tcpdump -i en1 -s 65535 -x port 3306

Turns out mk-query-digest would like a couple of other options so the output is formatted just right.  Include -q (quiet) -tttt (timestamp) and -n (don't IPs to names).  Send the results to a file like this:

$ tcpdump -i en1 -s 65535 port 3306 -x -q -n -tttt > mysql_tcpdump.txt

Hit Ctrl-C to stop collecting data.

How Do We Use Maatkit to Analyze Query Log?

Maatkit is an incredible toolset for MySQL by Baron Schwartz.  It includes tools to monitor & verify replication, review, profile and analyze queries, peek into your error logs, log deadlocks, and a whole lot more.

For our purposes, we'll be interested in the main query summarizing tool called mk-query-digest.  This tool, with no options takes a slow query log as its only option, churns through it for you and sorts queries by the heaviest ones.

First, let's install it.  

$ wget http://www.maatkit.org/get/mk-query-digest
$ chmod +x mk-query-digest

Simple installation!  Now run it on your slow query log, for example:

$ mk-query-digest /var/lib/mysql/mysqld
 
# 27.2s user time, 500ms system time, 28.90M rss, 118.84M vsz
# Current date: Wed Nov 17 18:12:50 2010
# Hostname: iheavy.com
# Files: mysqld-slow.log
# Overall: 113.33k total, 146 unique, 0.01 QPS, 0.00x concurrency ________
# Time range: 2010-04-09 04:18:07 to 2010-11-17 18:12:07
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          2297s       0     10s    20ms       0   303ms       0
# Lock time            12s       0      1s   105us       0    10ms       0
# Rows sent         85.21M       0 484.03k  788.45  174.84  15.31k    0.99
# Rows examine     100.73M       0 484.03k  932.08  563.87  15.31k   11.95
# Query size        14.95M      21     505  138.33  346.17   91.29  118.34
 
# Profile
# Rank Query ID           Response time    Calls R/Call   Apdx V/M   Item
# ==== ================== ================ ===== ======== ==== ===== =====
#    1 0x67A347A2812914DF  1989.0000 86.6% 13027   0.1527 0.98  4.95 SELECT pn_reviews_comments
#    2 0x88ADEFD1BC88F8BB   217.0000  9.4% 26319   0.0082 1.00  0.98 SELECT wp_posts
# MISC 0xMISC                91.0000  4.0% 73979   0.0012   NS   0.0 <144 ITEMS>

This is the output for my server, which primarily hosts a few blogs.  As you can quickly see from this output, almost 87% of the time is spent on this one query hitting pn_reviews_comments table.  Searching further down, it turns out this has an SQL_NO_CACHE directive, *AND* it's doing a select * so getting all of the rows each time.  No wonder it's slow.

The last thing you'll want to think about is looking at queries within a certain window.  You can do that by specifying a date & time to start with and another date & time to end with.  For example if I want to look at only slow queries since Oct 1st, I'd use this command:

$ mk-query-digest --since '2010-10-01 00:00:00' --until '2010-11-30 00:00:00'
/var/lib/mysql/mysqld

How Does mk-query-digest Work With A Tcpdump Stream?

Now that we know how to use mk-query-digest, we have two options.  We can hand the tcpdump output file directly to mk-query-digest such as the following:

$ mk-query-digest --type tcpdump mysql_tcpdump.txt

Alternatively, you can use a pipe and send the output of tcpdump right to mk-query-digest like this:

$ tcpdump -i en1 -s 65535 port 3306 -x -q -n -tttt | mk-query-digest --type tcpdump 

Again, when you're finished hit Ctrl-C and your query report will be printed to your terminal.  As a final recommendation, you might want to send that report to a text file as follows:

$ tcpdump -i en1 -s 65535 port 3306 -x -q -n -tttt | mk-query-digest --type tcpdump  > mysql_query_report.txt

And finally view your report:

$ less mysql_query_report.txt

Conclusion

mk-query-digest is a very powerful query analysis tool that no MySQL DBA should do without.  It provides great insight on what types of queries are heaviest, and which will be bogging down your MySQL server.  Couple that with a tcpdump stream, and you have an almost instant diagnostic tool at the ready.

» See All Articles by Columnist Sean Hull