Troubleshooting MySQL Slow Queries with Tcpdumps
December 21, 2010
MySQL has a wonderful facility for capturing slow queries called the slow query log. However if yours is not enabled when trouble occurs, and restarting the database is not an option, you'll need another solution. This is where a tcpdump can come in handy. It can be used to watch a network interface and display the packets and traffic.
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
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.