Have you ever wondered how optimized your Memcached installation is? There is a common misconception that one doesn’t have to think too deeply about Memcached performance, but that is not true. If your setup is inefficient, you could:

  • Burn Memory
  • Waste Network Round-Trips
  • Store Keys That Never Get Retrieved
  • Have a Low Cache Hit Ratio (i.e. query MySQL too much)
  • Suffer a fate too horrible to contemplate.

Percona does a lot of consulting around Memcached, so we try to take a quantitative, scientific approach to measuring memcached performance, just like everything else we do.

memcached is basically a key-value in-memory database, so it works well to analyze its traffic with Maatkit’s mk-query-digest tool. You can now use mk-query-digest to get “query event” information and report on memcached effectiveness. As far as we know, this is the first and only tool of its kind.

The output is very similar to that which would be displayed for MySQL queries. Commands are fingerprinted so that similar things can be aggregated together. The output begins with an overall report:

We can see that 77% of commands (cmds) were get, 17% set, 4% delete and 4 incr (increment) cmds. At present, Memc_error only refers to gets (or, retrieval cmds in general) that were interrupted (some things are TODO). Memc_miss is for any cmd that resulted in a NOT_FOUND result. So in this case, 15% of all cmds tried to do something with a nonexistent key.

The next bit aggregates similar queries into classes and prints out the most expensive ones. Here’s the top one:

Interestingly, apparently 17% of all “get TEST_KEY” were interrupted (Memc_error), probably by the TCP connection being closed client-side.

You’ll notice 100% Memc_get. This is a result of the default –report and –group-by, which is “fingerprint” just like for slow query logs. So the fingerprint for this event is “get TEST_KEY” and since the cmd is “get”, 100% Memc_get. There’s another way to aggregate — by the fingerprinted key, omitting the verb (get/set/etc). To do this, you’d specify key_print as the group-by value. More details are below.

This feature is still in beta. Some things are TODO; the report format could be cleaned up a little, etc. But we’re releasing early and often, and we’re calling on the community to help us out with testing! Here’s how:

  1. Get the latest mk-query-digest
  2. Capture memcached network traffic with tcpdump
  3. Parse memcached network traffic with mk-query-digest
  4. Ponder the results, or consider a different –report option

In code:

Depending on what you’re interested in, you may want to try these other reports:

  • –report key_print: Group events by a fingerprinted version of keys. So “get user_123” and “set user_456” are grouped together because the key_print for both is “user_?”. Doing this, per-class results will have various percentages for Memc_get, Memc_set, etc. instead of 100% Memc_cmd like above.
  • –report key: Like key_print but the keys are not fingerprinted so the two examples above are different classes because “user_123” != “user_456”. This would allow you to see per-key stats. Maybe, for example, how often a certain key is get’ed in comparison to other keys. (I.e. “what’s the most popular get’ed or set’ed key” etc.)
  • –report cmd: Group events by cmd. So “get user_123” and “get whatever” are grouped together because both are “get” cmds. You may want to do this to see, for example, what percentage of get cmds miss, i.e. result in NOT_FOUND.

These instructions could change in the future — this blog post is not authoritative documentation. The most current documentation is always embedded in the tool itself, and is readable with perldoc! Let us know what you think. Please use the Maatkit mailing list and and post bug reports on Google Code.

12 Comments
Oldest
Newest Most Voted
Inline Feedbacks
View all comments
Piotr

I have

root@lb2:~# ./mk-query-digest –type memcached memc_tcpdump.txt
# mk_query_digest:6381 6920 Use of uninitialized value in string eq at ./mk-query-digest line 5363, chunk 1.
#
# mk_query_digest:6381 6920 Use of uninitialized value in string eq at ./mk-query-digest line 5363, chunk 2.
#

0
Ryan

Hey Piotr,

How’d you capture tcpdump info? Also, it doesn’t yet understand IPv6. Send Daniel the tcpdump output. And let’s put bug reports on Google Code:)

0
Gavin Towey

When I try to use it, it just gives lots of these lines:

./mk-query-digest –type memcached memc_tcpdump.txt

# mk_query_digest:6758 5136 tell() on closed filehandle at ./mk-query-digest line 2019.

0
DLS

I also get errors:

# mk_query_digest:6758 29461 Use of uninitialized value in pattern match (m//) at mk-query-digest line 2045, chunk 2972.

Here’s how I captured tcpdump:

tcpdump -s 65535 -v -x -n -q -tttt -i any port 11211 > memc_tcpdump.txt

0
Daniel Nichter

For those having issues parsing memcached dumps, I’ll be happy to fix them, but I’ll need a sample of your dump file that’s causing the crash. If your dump file doesn’t have private data, could you please create a new issue at http://code.google.com/p/maatkit/issues/list and upload the dump file? Else, you can email me your dump file, I’ll fix it and keep your data private; the address is my name at percona.com.

Also, if you haven’t tried the latest version already, try it: wget http://www.maatkit.org/trunk/mk-query-digest
I fixed some similar issues last week with memc parsing.

0
CaptTofu

Hi there!

I’m excited to try this out, but have similar problems shown here in the comments:

mk_query_digest:6758 23474 Use of uninitialized value $source in pattern match (m//) at /usr/bin/mk-query-digest line 2045, chunk 180.

Many lines of this – I even tried to make modifications to not apply the regex if not defined, but I’m not getting anywhere with it.

The tcpdump command options:

tcpdump -s 65535 -v -x -n -q -tttt -i any port 11211 > memc_tcpdump.txt

Any suggestions?

Thanks!

0
Daniel Nichter

CaptTofu, I see you commented on http://code.google.com/p/maatkit/issues/detail?id=544 and that you fixed this by removing the -v option from tcpdump?

Currently, the tcpdump output must be like:

2009-07-04 21:33:39.229179 IP 127.0.0.1.35126 > 127.0.0.1.11211: tcp 31
0x0000: 4500 0053 1d2a 4000 4006 1f79 7f00 0001
0x0010: 7f00 0001 8936 2bcb d4c3 3924 d4c8 1de4
0x0020: 8018 0201 fe47 0000 0101 080a 0008 240b
0x0030: 0008 240b 7365 7420 6d79 5f6b 6579 2030
0x0040: 2030 2031 300d 0a53 6f6d 6520 7661 6c75
0x0050: 650d 0a

So you may need to tweak your tcpdump options to get the output correct. Any extra info will confuse the tcpdump parser and cause these kinds of errors.

0
Daniel Nichter

Due to loss of formatting, the above sample output is missing spaces before each hex dump line.

0
CaptTofu

Daniel,

removing the -v helped, but a later run, even without the -v, gave me the error. It was a huge dump file, and strangely, while I was doing this, my amazon instance kicked me out and wouldn’t let me back in (not related I’m sure!) So I have no way of obtaining that file that was giving me problems.

0
Andrei

Nice post. I want to add that if you run memcached server on a non-11211 port, you need to add –watch-server to mk-query-digest or you will get “Packet is not to or from memcached server” error.

0
Adam Monsen

@CaptTofu – hi Patrick!

I was seeing this:

Pipeline process 3 (TcpdumpParser) caused an error: Use of uninitialized value $source in pattern match (m//) at /usr/bin/pt-query-digest line 2676, chunk 1.
Pipeline process 3 (TcpdumpParser) caused an error: Use of uninitialized value $source in pattern match (m//) at /usr/bin/pt-query-digest line 2676, chunk 2.
Pipeline process 3 (TcpdumpParser) caused an error: Use of uninitialized value $source in pattern match (m//) at /usr/bin/pt-query-digest line 2676, chunk 3.
…

when running memcached on localhost and running pt-query-digest on the tcpdump output as documented. I tried again, instead telling memcached to bind to a particular IP address (memcached -l 10.0.2.15), and then everything magically started working.

0
Sunchaser

hello i have memcache failing with this error:

2013-07-10 00:29:30 +02:00 — error: Uncaught PHP Error: Memcache::set() [memcache.set]: Server 127.0.0.1 (tcp 11211) failed with
: Failed reading line from stream (0) in file system/libraries/drivers/Cache/Memcache.php on line 111

I tcpdumped memcache but when i try to analyze it with percona i have the following output

root@host [~/mytools]# percona/mk-query-digest memcached.tcp.txt

# 230ms user time, 10ms system time, 23.53M rss, 72.28M vsz
# Current date: Wed Jul 10 10:20:35 2013
# Hostname: host.medieval-europe.eu
# Files: memcached.tcp.txt
# Overall: 0 total, 1 unique, 0 QPS, 0x concurrency ______________________
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Query size 695.80k 695.80k 695.80k 695.80k 695.80k 0 695.80k

# Profile
# Rank Query ID Response time Calls R/Call Apdx V/M Ite
# ========== ========== ========== ========== ========== ==== ===== ======

Any help please? i don’t see any output.

extract of tcpdump:

2013-07-10 10:16:51.439799 IP 127.0.0.1.40081 > 127.0.0.1.11211: tcp 0
0x0000: 4500 003c 2d24 4000 4006 0f96 7f00 0001
0x0010: 7f00 0001 9c91 2bcb 9c96 2436 0000 0000
0x0020: a002 8018 f0ec 0000 0204 400c 0402 080a
0x0030: 0c65 0912 0000 0000 0103 0307
2013-07-10 10:16:51.440615 IP 127.0.0.1.11211 > 127.0.0.1.40081: tcp 0
0x0000: 4500 003c 0000 4000 4006 3cba 7f00 0001
0x0010: 7f00 0001 2bcb 9c91 9c68 15f7 9c96 2437
0x0020: a012 8000 291d 0000 0204 400c 0402 080a
0x0030: 0c65 0912 0c65 0912 0103 0307
2013-07-10 10:16:51.440626 IP 127.0.0.1.40081 > 127.0.0.1.11211: tcp 0
0x0000: 4500 0034 2d25 4000 4006 0f9d 7f00 0001
0x0010: 7f00 0001 9c91 2bcb 9c96 2437 9c68 15f8
0x0020: 8010 0101 1141 0000 0101 080a 0c65 0912
0x0030: 0c65 0912
2013-07-10 10:16:51.440635 IP 127.0.0.1.40081 > 127.0.0.1.11211: tcp 43
0x0000: 4500 005f 2d26 4000 4006 0f71 7f00 0001
0x0010: 7f00 0001 9c91 2bcb 9c96 2437 9c68 15f8
0x0020: 8018 0101 fe53 0000 0101 080a 0c65 0912
0x0030: 0c65 0912 6765 7420 6d65 6c69 7665 5f77
0x0040: 696b 693a 6170 6971 7565 7279 6765 6e65
0x0050: 7261 746f 7273 3a31 2e32 302e 330d 0a
2013-07-10 10:16:51.440651 IP 127.0.0.1.11211 > 127.0.0.1.40081: tcp 0
0x0000: 4500 0034 1cea 4000 4006 1fd8 7f00 0001
0x0010: 7f00 0001 2bcb 9c91 9c68 15f8 9c96 2462
0x0020: 8010 0100 1117 0000 0101 080a 0c65 0912
0x0030: 0c65 0912
2013-07-10 10:16:51.439801 IP 127.0.0.1.11211 > 127.0.0.1.40081: tcp 5
0x0000: 4500 0039 1ceb 4000 4006 1fd2 7f00 0001
0x0010: 7f00 0001 2bcb 9c91 9c68 15f8 9c96 2462
0x0020: 8018 0100 fe2d 0000 0101 080a 0c65 0912
0x0030: 0c65 0912 454e 440d 0a
2013-07-10 10:16:51.439814 IP 127.0.0.1.40081 > 127.0.0.1.11211: tcp 0
0x0000: 4500 0034 2d27 4000 4006 0f9b 7f00 0001
0x0010: 7f00 0001 9c91 2bcb 9c96 2462 9c68 15fd
0x0020: 8010 0101 1111 0000 0101 080a 0c65 0912
0x0030: 0c65 0912
2013-07-10 10:16:51.477871 IP 127.0.0.1.40081 > 127.0.0.1.11211: tcp 572
0x0000: 4500 0270 2d28 4000 4006 0d5e 7f00 0001
0x0010: 7f00 0001 9c91 2bcb 9c96 2462 9c68 15fd
0x0020: 8018 0101 0065 0000 0101 080a 0c65 0938
0x0030: 0c65 0912 7365 7420 6d65 6c69 7665 5f77
0x0040: 696b 693a 6170 6971 7565 7279 6765 6e65
0x0050: 7261 746f 7273 3a31 2e32 302e 3320 3120

0