For the last couple of months, we've been quietly developing a MySQL protocol parser for Maatkit. It isn't an implementation of the protocol: it's an observer of the protocol. This lets us gather queries from servers that don't have a slow query log enabled, at very high time resolution.
With this new functionality, it becomes possible for mk-query-digest to stand on the sidelines and watch queries fly by over TCP. It is only an observer on the sidelines: it is NOT a man in the middle like mysql-proxy, so it has basically zero impact on the running server (tcpdump is very efficient) and zero impact on the query latency. There are some unique challenges to watching an entire server's traffic, but we've found ways to solve those. Some of them are harder than others, such as making sense of a conversation when you start listening in the middle. In general, it's working very well. We can gather just about every bit of information about queries that mysql-proxy can, making this a viable way to monitor servers without the disadvantages of a proxy. In theory, we can gather ALL the same information, but in practice we are going for the 95% case.
As always with Maatkit, this has minimal dependencies. It doesn't require any Net::Pcap or other modules from CPAN. It's written in pure Perl, and it parses the output of tcpdump, rather than watching the network traffic directly. This might sound useless, but it's not. It means you can go tcpdump some traffic on a machine without Perl installed, and copy it to another machine for analysis, or send it via email to your friendly consultant, or do any of a number of other things. Decoupling things is very helpful sometimes.
Let's see how to gather queries and do something useful with them. I'll just watch the queries on a sandbox server on my laptop, and print out the profile synopsis so you can see how it works.
-
sudo tcpdump -i lo port 3306 -s 65535 -x -n -q -tttt> tcpdump.out
I run a few queries, quit, and cancel tcpdump. Now I've got a file and I'm ready to analyze it. Let's see:
-
mk-query-digest --type=tcpdump --report-format=profile tcpdump.out
-
# Rank Query ID Response time Calls R/Call Item
-
# ==== ================== ================ ======= ========== ====
-
# 1 0x088084BF139954D8 0.1009 90.2% 1 0.100881 SELECT dual
-
# 2 0x261703E684370D2C 0.0110 9.8% 1 0.011017
I'm kind of showing off the summary profile here to illustrate that you can get really compact results to see what's going on inside your server. What do you suppose that one query was that took a tenth of a second? We can find out.
-
mk-query-digest --type=tcpdump --limit 1 tcpdump.out
-
# 460ms user time, 30ms system time, 8.88M rss, 11.79M vsz
-
# Overall: 8 total, 6 unique, 0.15 QPS, 0.00x concurrency ________________
-
# total min max avg 95% stddev median
-
# Exec time 114ms 0 101ms 14ms 100ms 33ms 737us
-
# Hosts 8
-
# Time range 2009-07-01 23:55:41.334082 to 2009-07-01 23:56:33.929945
-
# bytes 215 14 49 26.88 46.83 9.76 26.08
-
# Errors 8
-
# Rows affe 0 0 0 0 0 0 0
-
# Warning c 0 0 0 0 0 0 0
-
# 0% No_good_index_used
-
# 12% No_index_used
-
-
# Query 1: 0 QPS, 0x concurrency, ID 0x088084BF139954D8 at byte 7517 _____
-
# This item is included in the report because it matches --limit.
-
# pct total min max avg 95% stddev median
-
# Count 12 1
-
# Exec time 88 101ms 101ms 101ms 101ms 101ms 0 101ms
-
# Users 1 msandbox
-
# Hosts 1 127.0.0.1
-
# Databases 1
-
# Time range 2009-07-01 23:56:31.022602 to 2009-07-01 23:56:31.022602
-
# bytes 22 49 49 49 49 49 0 49
-
# Errors 1 none
-
# Rows affe 0 0 0 0 0 0 0 0
-
# Warning c 0 0 0 0 0 0 0 0
-
# 0% No_good_index_used
-
# 0% No_index_used
-
# Query_time distribution
-
# 1us
-
# 10us
-
# 100us
-
# 1ms
-
# 10ms
-
# 100ms ################################################################
-
# 1s
-
# 10s+
-
# Tables
-
# SHOW TABLE STATUS LIKE 'dual'\G
-
# SHOW CREATE TABLE `dual`\G
-
# EXPLAIN
-
select 1 from ( select sleep(.1) from dual ) as x\G
Indeed, it's no surprise the query took a tenth of a second to execute, and now you see where "SELECT dual" comes from.
Notice that it is inspecting the protocol enough to see the flags set in the protocol, indicating the warning count, error count, rows affected, and whether no index or no good index was available. Look at the top of the report -- what is up with the 12% of queries that say No_index_used? If we increase --limit a bit, we can see
-
# 0% No_good_index_used
-
# 100% No_index_used
-
# Query_time distribution
-
... snip ...
-
show databases\G
I did not know that SHOW DATABASES sets the "no index used" flag, did you? Now we both do!
This is just a brief introduction to what the protocol parser can do. Of course, in real life it's much more useful than just seeing a query or two -- it has all the power of mk-query-digest for filtering, aggregating, printing and so forth.
Entry posted by Baron Schwartz | 2 comments
Add to: 
| 
| 
| 
| 
