Unexpected (and failing) cache GETs #7581

Closed
shyam-habarakada opened this Issue Sep 9, 2012 · 20 comments

Projects

None yet

10 participants

@shyam-habarakada

My rails 3.2 app is trying to fetch values from the cache (memcached via dalli) that I'm not expecting it to be caching. It's not getting any cache hits, but I'm puzzled about what is going on. This happens with config.action_controller.perform_caching = true on production as well as development, using WEBrick.

Here's a snippet of what I'm seeing in memcache verbose output:

<30 GET https://www.myrailsapp.com/?
>30 Writing an error: Not found
>30 Writing bin response:
>30   0x81 0x00 0x00 0x00
>30   0x00 0x00 0x00 0x01
>30   0x00 0x00 0x00 0x09
>30   0x00 0x00 0x00 0x00
>30   0x00 0x00 0x00 0x00
>30   0x00 0x00 0x00 0x00
<30 Read binary protocol data:
<30    0x80 0x00 0x00 0xd0
<30    0x00 0x00 0x00 0x00
<30    0x00 0x00 0x00 0xd0
<30    0x00 0x00 0x00 0x00
<30    0x00 0x00 0x00 0x00
<30    0x00 0x00 0x00 0x00

Note that there is only a cache GET and I'm not seeing any cache writes.

I see similar cache GET attempts for all my actions, most of which are JSON API calls. All of them result in a cache miss. Like this,

<31 GET https://www.myrailsapp.com/api/somecall?param1=foo&param2=bar
>31 Writing an error: Not found

I have not specified any caches_action directives anywhere in my app.

Is this a rails bug?

If no, where should I look to stop these unnecessary cache GETs?

@shyam-habarakada

This issue on dalli and the associated stack overflow question about how to prevent-cache-miss-warnings-with-perform-caching-on seem related, but don't explain why rails is trying to GET these objects from the cache in the first place.

@rafaelfranca
Ruby on Rails member

Perhaps because the Rails application is using the memcache session store.

@shyam-habarakada

This is my memcache config. Development is the same except debug being set to true.

memcache_options = {
  :debug => false,
  :readonly => false
}
memcache_servers = "localhost"
config.cache_store = :dalli_store, memcache_servers, memcache_options
@rafaelfranca
Ruby on Rails member

I don't know how dalli works but maybe @guilleiguaran knows.

@shyam-habarakada

I doubt this is dalli or memcache specific, although I'm yet to try the scenario with a different cache or cache client.

@frodsan

@shyam-habarakada Hi, could you provide a sample app to reproduce this problem? It's really difficult to figure out the issue with this information. Thanks.

@shyam-habarakada

@frodsan here are steps to reproduce.

  1. Setup a new rails app
  2. Install memcached and run it in interactive, verbose mode (in a console/terminal)
  3. Configure dalli as the memcached client
  4. Navigate to pages on the new rails app and observe output in the memcached terminal. You'll notice that it's trying to fetch what appears to be like page fragments from the cache.
@migmartri

Same problem here, I get a missing GET memcached request for every page I visit. Using either dalli_store or mem_cache_store cache backend. Having enabled the rails assets does not affects to the behavior either.

Rails 3.2.8

@parndt

So is this a problem in Rails or a problem in dalli? Have you managed to try with a different cache client?

@shyam-habarakada

I have not tried other clients. That said, I doubt very much that it is a dalli issue. As you can see in the verbose traces above, the cache GET is coming from somewhere above dalli in the call stack. That would be rails.

@migmartri

I have used plain mem_cache_store and still can see those calls. So I do not think that this is dalli issue.

@mgartner

I'm seeing the same unexpected cache GETs as well. Has anyone done more research into this issue? Any idea on how badly this affects the performance of an app?

@lukaszx0
Ruby on Rails member

I've noticed same thing in my logs today and found this issue. Looks like it's still an issue on rails 3.2.12, but appears to be fixed in master.

I guess this can be closed then.

@steveklabnik
Ruby on Rails member

I'll tag with 3-2-stable.

@lukaszx0
Ruby on Rails member

I'll provide some feedback then. Reproducing is simple. I've created new bare rails app foobar, controller with action index and set perform_caching to true in config.

After requesting index action I've got this in memcache -vv output:

<22 GET http://foobar.dev/test/index?
>22 Writing an error: Not found
@Genkilabs

Reproduced on Rails 3.2.13 and Dalli 2.6.2.

@cswilliams

I just checked out 3-2-stable and the issue still exists. I got a bracktrace from when it tries to read the key from memcached. It appears that Rack::Cache's MetaStore is responsible. Not sure if this is intended behavior or what, but it sure generates quite a bit of useless memcache lookups on a busy app.

/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/dalli-1.1.5/lib/active_support/cache/dalli_store.rb:121:in `read_entry'
/Users/cswilliams/Desktop/rails/activesupport/lib/active_support/cache/strategy/local_cache.rb:134:in `read_entry'
/Users/cswilliams/Desktop/rails/activesupport/lib/active_support/cache.rb:316:in `block in read'
/Users/cswilliams/Desktop/rails/activesupport/lib/active_support/cache.rb:520:in `instrument'
/Users/cswilliams/Desktop/rails/activesupport/lib/active_support/cache.rb:315:in `read'
/Users/cswilliams/Desktop/rails/actionpack/lib/action_dispatch/http/rack_cache.rb:17:in `read'
/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/rack-cache-1.2/lib/rack/cache/metastore.rb:30:in `lookup'
/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/rack-cache-1.2/lib/rack/cache/context.rb:169:in `lookup'
/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'
/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/Users/cswilliams/Desktop/rails/railties/lib/rails/engine.rb:484:in `call'
/Users/cswilliams/Desktop/rails/railties/lib/rails/application.rb:231:in `call'
/Users/cswilliams/Desktop/rails/railties/lib/rails/railtie/configurable.rb:30:in `method_missing'
/Users/cswilliams/.rvm/gems/ruby-1.9.3-p125@rails3/gems/passenger-3.0.13/lib/phusion_passenger/rack/request_handler.rb:96:in `process_request'
@cswilliams

Just wanted to add some more useful information. As noted by strzalek, this issue doesn't appear in master anymore. I believe the reason is due to this commit, which disables rack cache by default:
586a991

I was able to fix my app by adding the following to my environment's configuration:
config.action_dispatch.rack_cache = false

I can't say I'm all that familiar with rack cache, so hopefully disabling this has no unwanted side-effects, but my app seems normal after disabling it and making a lot less memcache requests now.

@steveklabnik
Ruby on Rails member

Since this doesn't appear in master any more, I'm giving it a close. Thanks!

@steveklabnik
Ruby on Rails member

(If someone wants to fix it for 3-2-stable, please send a pull request.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment