Slow cache read on first cache fetch in Rails

Question

I am seeing some very slow cache reads in my rails app. Both redis (redis-rails) and memcached (dalli) produced the same results.

It looks like it is only the first call to Rails.cache that causes the slowness (averaging 500ms).

I am using skylight to instrument my app and see a graph like:

I have a Rails.cache.fetch call in this code, but when I benchmark it I see it average around 8ms, which matches what memcache-top shows for my average call time.

I thought this might be dalli connections opening slowly, but benchmarking that didnt show anything slow either. I'm at a loss for what else to check into.

Does anyone have any good techniques for tracking this sort of thing down in a rails app?

Edit #1

Memcache server is stored in ENV['MEMCACHE_SERVERS'], all the servers are in the us-east-1 datacenter.

Cache config looks like:

  config.cache_store = :dalli_store, nil, { expires_in: 1.day, compress: true }

I ran something like:

100000.times { Rails.cache.fetch('something') }

and calculated the average timings and got something on the order of 8ms when running on one of my webservers.

Testing my theory of the first request is slow, I opened a console on my web server and ran the following as the first command.

irb(main):002:0> Benchmark.ms { Rails.cache.fetch('someth') { 1 } }
Dalli::Server#connect my-cache.begfpc.0001.use1.cache.amazonaws.com:11211
=> 12.043342

Edit #2

Ok, I split out the fetch into a read and write, and tracked them independently with statsd. It looks like the averages sit around what I would expect, but the max times on the read are very spiky and get up into the 500ms range.

http://s16.postimg.org/5xlmihs79/Screen_Shot_2014_12_19_at_6_51_16_PM.png