November 27, 2014

How to use tcpdump on very busy hosts

Often I run into problems when trying to use mk-query-digest with tcpdump on “very” busy hosts. You might be thinking, “very busy is a relative and unquantifiable term,” and you’d be right, so I’ll phrase this differently. Let me give a little background to the problem first. Mk-query-digest tries to handle dropped or missing packets gracefully, but even so they can skew results dramatically. Imagine a situation where a single connection sends two queries and gets two responses, with a response time of R for each request, and a wait time of W between the requests. If the first response and second request are dropped by the kernel, the result – from mk-query-digest’s perspective – is that the database took 2R + W time to respond to the first request.

Back to the question of, “what is a very busy host?” In my experience, if you are getting even 5% of tcpdump packets dropped by the kernel, the results can be skewed enough to cause confusion about which queries are really slow. Recently, I got more than 60% dropped packets on a server with roughly 50MB/s of traffic on port 3306, system load of about 10, and 8 CPU cores. The resulting mk-query-digest output was obviously bogus when compared to the host’s slow-query-log (for example, none of the top 5 slow queries reported by mkqd appeared in the actual slow log file). After a little brain-storming, we came up with a few solutions:

  1. use “mk-query-digest –filter ‘$event->{time} && $event->{time} > 1′” to exclude all queries which it believes took longer than the servers long-query-time of 1 second
  2. tcpdump traffic only from a small and representative subset of clients
  3. tcpdump a modulo of incoming ports (including port 3306, because we must capture the responses from mysqld)

#1 has an obvious flaw — if your long-query-time is 1 second, and mkqd believes that a query which actually took 10ms instead took 0.9s, the results are still useless. That is to say, this doesn’t actually solve the real problem of dropped packets, it just applies a mask to the output. #2 seems like the simplest good solution, but when I tested this, I still got very high percentage of dropped packets (around 30% when filtering only 4 out of hundreds of active clients). While this is lower than without the filter, it is still unusable. #3 actually worked very well and resulted in about 0.2% packet loss on this host, which is acceptable — the variances are statistically smoothed out and don’t noticeably affect the results. Here is the tcpdump command used.

I also had to forward the tcpdump output to another host for processing because the database host couldn’t handle the additional IO or CPU pressure of either writing it to a file or piping it to mk-query-digest. Here is a draft of a script to automate this; use at your own risk and update to suit your needs.

 

About Devananda van der Veen

Deva is a former Percona employee.
Deva joined Percona in July 2009 as a Principal Consultant, with a focus on scalability and performance tuning. Deva has a background in physics and computer science from UC Santa Barbara. Prior to joining Percona, he was the DBA at HydraNetwork.

Comments

  1. Baron Schwartz says:

    I just used this trick, worked like a charm.

    207815 packets captured
    214152 packets received by filter
    6324 packets dropped by kernel

  2. Anthony DeRobertis says:

    Another approach, if you have the hardware: enable port mirroring on your switch, and capture the traffic on an otherwise idle host with enough disk bandwidth to do so.

  3. erkules says:

    Devananda .. right I missed that.

  4. Devananda van der Veen says:

    erkules, “dst port 3306″ won’t work because you must also capture the reply from mysqld, where the source port is 3306 and the dest port is unknown (matches & 7 == 2).

    In some cases, I’m sure that host filtering would work fine, eg when you want to watch a specific host, but in some situations I’ve faced it does not work well. Honestly, I’m not sure why the packet drops were so high when filtering just a few hosts, perhaps the CPU overhead is higher when applying a host IP filter versus a port bitmask filter?

  5. erkules says:

    Ahh of course no effect is wrong. At least of the ports got to be 3306 (port=3306) the AND check for that dst/src-port is fulfilled anyway (3306) and the other one got to fullfill &7 == 2.

    So one could use instead “dst port 3306″ to match mysql server and do some portfiltering on tcp[0,1] I would prefer hosts.

  6. erkules says:

    On this example it has no effect, as port 3306 is more precise. tcp[0,1] sourceport and tcp[2,3] dstport (rfc 793).

  7. Devananda van der Veen says:

    tcp[x] indicates the x’th octet in the TCP header, starting from 0. The first two octets are the source port, second two octets are the destination port. So my understanding is that this expression says: the lower octet of each source and dest port, when AND’ed with the bitmask ’111′ result in a value of ’010′, or the number 2. Note that “3306 & 7 == 2″ is a true statement.

    See http://www.tcpdump.org/tcpdump_man.html for more in-depth info on TCP header structure.

  8. Baron Schwartz says:

    I’m not very fresh on my TCP headers and I don’t remember what’s in various positions. What is the net effect of this expression?

    tcp[1] & 7 == 2 and tcp[3] & 7 == 2

  9. I’m not very fresh on my TCP headers and I don’t remember what’s in various positions. What is the net effect of this expression?

    tcp[1] & 7 == 2 and tcp[3] & 7 == 2

  10. tcp[x] indicates the x’th octet in the TCP header, starting from 0. The first two octets are the source port, second two octets are the destination port. So my understanding is that this expression says: the lower octet of each source and dest port, when AND’ed with the bitmask ‘111’ result in a value of ‘010’, or the number 2. Note that “3306 & 7 == 2″ is a true statement.

    See http://www.tcpdump.org/tcpdump_man.html for more in-depth info on TCP header structure.

  11. erkules says:

    On this example it has no effect, as port 3306 is more precise. tcp[0,1] sourceport and tcp[2,3] dstport (rfc 793).

  12. erkules says:

    Ahh of course no effect is wrong. At least of the ports got to be 3306 (port=3306) the AND check for that dst/src-port is fulfilled anyway (3306) and the other one got to fullfill &7 == 2.

    So one could use instead “dst port 3306″ to match mysql server and do some portfiltering on tcp[0,1] I would prefer hosts.

  13. erkules, “dst port 3306″ won’t work because you must also capture the reply from mysqld, where the source port is 3306 and the dest port is unknown (matches & 7 == 2).

    In some cases, I’m sure that host filtering would work fine, eg when you want to watch a specific host, but in some situations I’ve faced it does not work well. Honestly, I’m not sure why the packet drops were so high when filtering just a few hosts, perhaps the CPU overhead is higher when applying a host IP filter versus a port bitmask filter?

  14. erkules says:

    Devananda .. right I missed that.

  15. Anthony DeRobertis says:

    Another approach, if you have the hardware: enable port mirroring on your switch, and capture the traffic on an otherwise idle host with enough disk bandwidth to do so.

  16. I just used this trick, worked like a charm.

    207815 packets captured
    214152 packets received by filter
    6324 packets dropped by kernel

  17. Pascal Schmiel says:

    You can improve the rate even further if you first capture the traffic to a file using tcpdump’s “-w” option and parse it later with “tcpdump -r”.

    Using /usr/sbin/tcpdump -i eth1 -c 100000 -s0 -x -nn -q -tttt ‘port 3306 and tcp[1] & 7 == 2 and tcp[3] & 7 == 2′ | /usr/bin/mk-query-digest –type=tcpdump :

    100000 packets captured
    195794 packets received by filter
    95664 packets dropped by kernel

    And now using /usr/sbin/tcpdump -i eth1 -c 100000 -s0 -w /tmp/snoopfile ‘port 3306 and tcp[1] & 7 == 2 and tcp[3] & 7 == 2′; /usr/sbin/tcpdump -r /tmp/snoopfile -s0 -x -nn -q -tttt | /usr/bin/mk-query-digest –type=tcpdump :

    100000 packets captured
    100286 packets received by filter
    220 packets dropped by kernel

Speak Your Mind

*