Memcached weirdness...

digitalpoint

Well-known member
I've looked at this every way I can think of trying to get to the root of the issue, and haven't been able to come up with an idea of why I have so many CURRENT memcached items...

First of all, here's the relevant stats for my two memcached servers:

upload_2013-12-3_15-42-25.webp

So... I have more than 3 million current items across both memcached servers after a little over 9 days of them running.

First I decided to intercept memcache save/set calls from within XenForo to see exactly what's being set:
Code:
1386114216: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /threads/movie2kproxy-me-proxy-site-with-traffic.2695716/preview?_xfRequestUri=%2Fforums%2Fsites.52%2F&_xfNoRedirect=1&_xfResponseType=json - Mozilla/5.0 (Windows NT 6.1; WOW64; rv:25.0) Gecko/20100101 Firefox/25.0
1386114217: xf_node_ancestors_243_244                   (3600) - /threads/favourite-bollywood-actor-poll.834700/ - Mozilla/5.0 (iPhone; CPU iPhone OS 6_0 like Mac OS X) AppleWebKit/536.26 (KHTML, like Gecko) Version/6.0 Mobile/10A5376e Safari/8536.25 (compatible; Googlebot-Mobile/2.1; +http://www.google.com/bot.html)
1386114219: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /threads/forum-posting-service-niche-do-follow-high-pr.2677098/ - Mozilla/4.0
1386114220: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /forums/content-creation.102/page-2 - Mozilla/5.0 (Windows NT 6.1; WOW64; rv:25.0) Gecko/20100101 Firefox/25.0
1386114221: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /threads/email-subscription-script.705204/ - Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.57 Safari/537.36
1386114222: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /forums/-/index.rss - Mozilla/4.0 (Windows 98; US) Opera 10.00 [en]
1386114223: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /threads/i-need-directory-submmiters-for-3-80-000-submissions-within-5-days.1057869/ - Mozilla/5.0 (Windows NT 6.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.57 Safari/537.36
1386114224: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /?_xfResponseType=json - Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.57 Safari/537.36
1386114225: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /login/csrf-token-refresh - Mozilla/5.0 (Windows NT 6.1; rv:25.0) Gecko/20100101 Firefox/25.0
1386114226: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /forums/114/ - Mozilla/5.0 (Windows NT 6.2; WOW64; rv:16.0) Gecko/20100101 Firefox/16.0
1386114226: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /spy/feed?last=516827&r=0.01631981970558427 - Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1
1386114226: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /forums/-/index.rss - 
1386114230: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /forums/-/index.rss - Blogtrottr/2.0
1386114234: xf_post_areas148617                         (3600) - /members/seosharp.148617/post-areas?_xfRequestUri=%2Fmembers%2Fseosharp.148617%2F&_xfNoRedirect=1&_xfResponseType=json - Mozilla/5.0 (Linux; Android 4.4; Nexus 4 Build/KRT16S) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.59 Mobile Safari/537.36
1386114234: xf_session_xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (3600) - /members/seosharp.148617/post-areas?_xfRequestUri=%2Fmembers%2Fseosharp.148617%2F&_xfNoRedirect=1&_xfResponseType=json - Mozilla/5.0 (Linux; Android 4.4; Nexus 4 Build/KRT16S) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.59 Mobile Safari/537.36

So that is a sample from one (of four) web servers... the 3600 being recorded there is the expire time being set in the memcache call (session hashes removed for obvious reasons). As shown in item #3 of this bug report, search engine spiders aren't creating new sessions (cuts down on a massive number of memcached calls): http://xenforo.com/community/threads/caching-issues.63911/

So memcached usage initiated within XenForo looks normal... exactly as expected (mostly sessions with some other stuff here and there with most everything expiring in an hour). So in theory none of that stuff will be a current item in an hour from now unless it's refreshed.

I do have some other stuff that uses memcached, so I started thinking maybe I have something running wild saving a crazy amount of unexpiring stuff to memcached... So let's just look at the raw network traffic going to one of the memcached servers (I'm filtering sessions because there are a ton of them and we've already determined they expire in an hour as expected)...

In a 30 second sampling of the raw network traffic to memcached, it only had 12 items that were set when you don't include sessions...
Code:
tcpdump -XX -i ib0 dst host 192.168.10.20 and port 11211|grep set|grep -v xf_sess
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on ib0, link-type LINUX_SLL (Linux cooked), capture size 96 bytes
	0x0040:  fc90 665d 7365 7420 7866 5f74 7765 6574  ..f]set.xf_tweet
	0x0040:  fc90 6c2d 7365 7420 7368 6177 6e68 6f67  ..l-set.shawnhog
	0x0040:  fc90 6e40 7365 7420 7368 6177 6e68 6f67  ..n@set.shawnhog
	0x0040:  fc90 7292 7365 7420 7866 5f67 6574 5f63  ..r.set.xf_get_c
	0x0040:  fc90 7d02 7365 7420 7866 5f78 6643 7373  ..}.set.xf_xfCss
	0x0040:  fc90 7e39 7365 7420 7866 5f77 686f 6973  ..~9set.xf_whois
	0x0040:  fc90 8295 7365 7420 7866 5f70 6f73 745f  ....set.xf_post_
	0x0040:  fc90 82fc 7365 7420 7368 6177 6e68 6f67  ....set.shawnhog
	0x0040:  fc90 8536 7365 7420 7866 5f67 6574 5f63  ...6set.xf_get_c
	0x0040:  fc90 8626 7365 7420 7866 5f78 6643 7373  ...&set.xf_xfCss
	0x0040:  fc90 8f24 7365 7420 7368 6177 6e68 6f67  ...$set.shawnhog
	0x0040:  fc90 9364 7365 7420 7866 5f78 6643 7373  ...dset.xf_xfCss

All of those items show they are set to expire in memcache after 900-3600 seconds.

So now I'm just wondering, WTF... why do I have millions of "current" items in memcache, and if all those sessions are *actually* expiring after 1 hour, shouldn't the difference between current items and total items by much, much greater since that's the bulk of what's being set?

Anyone more familiar with the inner workings of memcached, like expired items still being counted as "current" for some reason and using memory?
 
Start your service with -o slab_reassign,slab_automove. Here it is mines:
Code:
[root@chronos ~]# ps -def | grep memcached
497       1356     1  0 Dec03 ?        00:00:26 /usr/bin/memcached -d -l 127.0.0.1 -p 11211 -U 11211 -P /var/run/memcached/memcached.pid -u memcached -o slab_reassign,slab_automove

Problem solved.
 
Start your service with -o slab_reassign,slab_automove. Here it is mines:
Code:
[root@chronos ~]# ps -def | grep memcached
497       1356     1  0 Dec03 ?        00:00:26 /usr/bin/memcached -d -l 127.0.0.1 -p 11211 -U 11211 -P /var/run/memcached/memcached.pid -u memcached -o slab_reassign,slab_automove

Problem solved.
This actually improved something I was looking into earlier. Thanks for sharing this
 
This actually improved something I was looking into earlier. Thanks for sharing this
Was a simple matter of adding -o slab_reassign,slab_automove into the /etc/memcached.conf and restarting memcached and php5-fpm. Since my sites aren't that busy I probably won't see any real current improvement - but now it's future proofed. :D
Thanks for the great tip @Floren!
 
Just what shows in the ps results... "-d -m 2048".

Can't use the slab_reassign,slab_automove options because I recently intentionally downgraded to memcached 1.2.8 and it was new to 1.4.x. It's fine though... not sure I would use the options even if I could because seems like it would add unnecessary overhead. I was mostly just wondering what my stats were about, and it just seems like memcached keeps stuff there until it needs space.
 
Top Bottom