no rails sql cache when reading from slaves

[bdarrow]

Rails/activerecord typically caches SQL statements if they are identical in the same request. Typically in the log it shows the query with the word 'CACHE' next to it for queries hitting the sql cache. Using octopus in a fully replicated setup, the SQL cache is not used when reading from slaves. Only read requests explicitly sent to the master ".using(:master)" provide caching (and similarly read requests in a transaction)

[brjennin]

Yeah, any updates on this? It's a pretty big issue for us since we rely on the cached SQL statements often in our app

[haidersabri]

+1 . we are using octopus for replication. using slaves is meant to scale db queries....not having rails cache seems to be counter productive.

[bdarrow]

I forked and resolved this issue in https://github.com/snappytv/octopus. Please feel free to test it out. Once I have a bit more time, I'll do some more testing myself and work with the octopus maintainers to pull this fix in.

[haidersabri]

bdarrow, thanks for the fork....do you have any updates on how that worked out?

[sobrinho]

@bdarrow can you make a pull request? :)

[thiagopradi]

Hi guys,

I found the issue with cache for slaves. The problem is that Rails uses a middleware (http://api.rubyonrails.org/classes/ActiveRecord/QueryCache.html) to enable/disable cache. and this middleware only enable/disable cache on the main connection. I'm working on a middleware for Octopus, in order to do SQL cache properly.

[eprothro]

@bdarrow, @haidersabri how did that fork end up treating y'all with respect to this issue?

@tchandy any idea on timeline for an update to fix this? Just curious if I can be of help.

[eprothro]

FYI, I integrated @bdarrow's proposed fix (rocketmobile@8b3f203). I didn't see a change in behavior.

2 Identical read queries were made during the same request, and the 2nd didn't come from cache.

@bdarrow are we missing something with how you intended this to be used? Perhaps in conjunction with ActiveRecord::Base.connection.cache blocks?

[thiagopradi]

@eprothro Sorry about the delay.

I'm working on a middleware solution for Octopus, but it isn't working yet.

Any update I'll ping you guys.

[eprothro]

No worries! Fantastic, thanks for the update. I may be authoring a dev center article soon regarding scaling via replication on the Heroku stack featuring octopus, and this is the only significant caveat remaining that I have to explain. Let me know if I can be of service in dev or testing, happy to help!

[rvaidya]

Hi there!

I have an issue related to this one, but from the opposite side. We have queries and we do NOT want them to be cached, since they otherwise would be pulling stale data. For the most part we are getting fresh data, but intermittently the data will be stale, probably due to what you had mentioned above about the "main connection" being cached.

Is your in progress middleware layer going to handle disabling caching as well?

Thanks.

[vishakhasawant]

Hi,
I am facing this issue with partially replicated mode too. Have you found any fix for this issue. I want to use this gem in production and this is the only hurdle to use it in production.

Thanks and Regards,

[thiagopradi]

Hi @eprothro , @vishakhasawant and all...

I did a small hack on the Octopus stack, to support query cache on slaves.. and it seems to be working!

Could anyone try it and see how it behaves on a real application? It's on this branch: https://github.com/tchandy/octopus/tree/new-cache-middleware

Btw, I don't encourage to run it on production, before testing on a staging server (or a local).

[vishakhasawant]

Hi, I have tested this on my local and it is working. However I feel it requires one round of regression cycle before putting it on production.
I got an update from you that you fixed rake db:migrate:reset issue too.Is it possible to have both these fixes on same branch?

Thank you for fixing these on priority,
Regards,

[eprothro]

Can you fork and rebase one on the other for your testing?

Thanks @tchandy, I'll give the caching patch a whirl!

On Jul 16, 2013, at 4:01 AM, Vishakha [email protected] wrote:

Hi, I have tested this on my local and it is working. However I feel it requires one round of regression cycle before putting it on production.
I got an update from you that you fixed rake db:migrate:reset issue too.Is it possible to have both these fixes on same branch?

Thank you for fixing these on priority,
Regards,

—
Reply to this email directly or view it on GitHub.

[eprothro]

A local test isn't working for me.

• My configuration failed to initialize with new-cache-middleware branch. I had to cherry-pick fd2aa0af36 to 8b3f2030a (the forked HEAD I'm using on production) to get things initialized correctly.

With a simple test on a Model marked as replicated_model

    def test_slave
      result = []
      Octopus.using(Octopus.shards_in(:followers)) do
        result = 10.times.map do
          {vehicle_count: Vehicle.scoped.count}
        end
      end

      result << {vehicle_count: Vehicle.scoped.using(Octopus.shards_in(:followers)).count}

      result << {vehicle_count: Vehicle.readonly.scoped.count}

      render json: result
    end

I see no caching used

11:37:04 web.1         | Processing by Web::PagesController#test_slave as HTML
11:37:04 web.1         | request_id= user= user_type= params={}
11:37:04 web.1         | [Shard: follower_2]   (20.5ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (21.6ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_2]   (15.8ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (15.5ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_2]   (22.3ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (12.2ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_2]   (19.9ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (18.5ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_2]   (15.1ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (12.5ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_1]   (13.0ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | [Shard: follower_2]   (16.9ms)  SELECT COUNT(*) FROM "vehicles"
11:37:04 web.1         | Completed 200 OK in 264ms (Views: 0.7ms | ActiveRecord: 214.2ms)

Whereas, when I initialize no shards:

1:34:28 web.1         | Processing by Web::PagesController#test_slave as HTML
11:34:28 web.1         | request_id= user= user_type= params={}
11:34:28 web.1         |    (12.9ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         |   CACHE (0.0ms)  SELECT COUNT(*) FROM "vehicles"
11:34:28 web.1         | Completed 200 OK in 39ms (Views: 0.7ms | ActiveRecord: 18.2ms)

Marking my shards.yml config as fully replicated made no difference.

[thiagopradi]

Hi @eprothro,

What version of rails are you using?

btw, query cache is enabled by a ActiveRecord middleware during the request. Could you force the cache before running your action? (using the following code):

ActiveRecord::Base.connection.enable_query_cache!

[eprothro]

@tchandy 3.2.13 and yes, I tried enabling explicitly in the 1st line of the
action as you suggested with no change :/

-Evan Prothro
Sent from my mobile

On Jul 16, 2013, at 9:19 PM, Thiago Pradi [email protected] wrote:

Hi @eprothro https://github.com/eprothro,

What version of rails are you using?

btw, query cache is enabled by a ActiveRecord middleware during the
request. Could you force the cache before running your action? (using the
following code):

ActiveRecord::Base.connection.enable_query_cache!

—
Reply to this email directly or view it on
GitHubhttps://github.com//issues/81#issuecomment-21088149
.

[thiagopradi]

@eprothro, are you using any special config or tricks?

I'll try to reproduce your case in the test suite.

[eprothro]

My config is exactly as described in the linked wiki page. As mentioned,
I'm not able to use the branch directly but cherry picked your caching fix
commit.

If you think it's my issue due to the cherry pick, no worries. I'll work to
get the Heroku config working with HEAD as soon as I have time. I just
wanted to let you know what I saw with your patch.

-Evan Prothro
Sent from my mobile

On Jul 16, 2013, at 9:36 PM, Thiago Pradi [email protected] wrote:

@eprothro https://github.com/eprothro, are you using any special config
or tricks?

I'll try to reproduce your case in the test suite.

—
Reply to this email directly or view it on
GitHubhttps://github.com//issues/81#issuecomment-21088602
.

[vishakhasawant]

@tchandy
I started using your branch in regression cycle and found one discrepancy. Though record is updated in the database still shard is picking it from cache.
It seems it is not working if same action is get called on update. If new action get called then shard is executing query from database.

Regards,

[thiagopradi]

Thanks for the feedback @vishakhasawant and @eprothro,

I'll work more on this issue today. :)

[vishakhasawant]

Did you get chance to look at this issue?

[nickmarden]

@vishakhasawant, can you see my branch https://github.com/nickmarden/octopus/tree/nick/sql-cache-bugfix fixes the problem you are seeing? One of my clients was also seeing a problem in which old stale cache values were being served, so I added a patch to more aggressively clear the query cache each time enable_query_cache! is called.

[thiagopradi]

Hi @eprothro / @vishakhasawant ,

I merged the PR from @nickmarden on my branch (https://github.com/tchandy/octopus/tree/new-cache-middleware). It seems that the issues that you guys are having are fixed. could you confirm?

Maybe I can release a new version of Octopus with query cache support :)

Thanks

[thiagopradi]

Version 0.7.0 (https://github.com/tchandy/octopus/releases/tag/v0.7.0) supports query cache. Closing this issue.

[wherewelive]

I ran into a problem this past week running with rails 4.1.0, postgres and puma on heroku. Followed the wiki guide for installation and configuration exactly and calling the using method in a couple of controllers on two different models to send read only queries to a follower (nothing out of the ordinary). Deployed and all seemed to be working perfectly for about 12 hours. Randomly I would get a request timeout error that then snowballed into every request after (to that web instance) timing out.

I spent a few days investigating long requests making sure it was not something in the DB like poor SQL, database lock or other database issue (because we do a lot of database work in the background). I could not find anything so I removed octopus to see if that was the issue and all went back to normal.

Looking through newrelic I found a few 900,000ms requests in Middleware/Rack/ActiveRecord::QueryCache#call.

Here is the stack trace for one of the hung requests:

…ctive_record/connection_adapters/postgresql_adapter.rb: 589:in `exec'
…ctive_record/connection_adapters/postgresql_adapter.rb: 589:in `active?'
…/active_record/connection_adapters/abstract_adapter.rb: 313:in `verify!'
…record/connection_adapters/abstract/connection_pool.rb: 453:in `block in checkout_and_verify'
…ms/activesupport-4.1.0/lib/active_support/callbacks.rb:  82:in `run_callbacks'
…record/connection_adapters/abstract/connection_pool.rb: 452:in `checkout_and_verify'
…record/connection_adapters/abstract/connection_pool.rb: 353:in `block in checkout'/app/vendor/ruby-2.1.4/lib/ruby/2.1.0/monitor.rb: 211:in `mon_synchronize'
…record/connection_adapters/abstract/connection_pool.rb: 350:in `checkout'
…record/connection_adapters/abstract/connection_pool.rb: 265:in `block in connection'/app/vendor/ruby-2.1.4/lib/ruby/2.1.0/monitor.rb: 211:in `mon_synchronize'
…record/connection_adapters/abstract/connection_pool.rb: 264:in `connection'
…/ruby/2.1.0/gems/ar-octopus-0.8.4/lib/octopus/proxy.rb: 205:in `safe_connection'
…/ruby/2.1.0/gems/ar-octopus-0.8.4/lib/octopus/proxy.rb: 292:in `block in clear_query_cache'
…/ruby/2.1.0/gems/ar-octopus-0.8.4/lib/octopus/proxy.rb: 292:in `each'
…/ruby/2.1.0/gems/ar-octopus-0.8.4/lib/octopus/proxy.rb: 292:in `clear_query_cache'
…/ruby/2.1.0/gems/ar-octopus-0.8.4/lib/octopus/proxy.rb: 283:in `enable_query_cache!'
…ms/activerecord-4.1.0/lib/active_record/query_cache.rb:  34:in `call'
…record/connection_adapters/abstract/connection_pool.rb: 621:in `call'
…pack-4.1.0/lib/action_dispatch/middleware/callbacks.rb:  29:in `block in call'
…ms/activesupport-4.1.0/lib/active_support/callbacks.rb:  82:in `run_callbacks'
…pack-4.1.0/lib/action_dispatch/middleware/callbacks.rb:  27:in `call'
…pack-4.1.0/lib/action_dispatch/middleware/remote_ip.rb:  76:in `call'
…1.0/lib/action_dispatch/middleware/debug_exceptions.rb:  17:in `call'
….1.0/lib/action_dispatch/middleware/show_exceptions.rb:  30:in `call'
…uby/2.1.0/gems/railties-4.1.0/lib/rails/rack/logger.rb:  38:in `call_app'
…uby/2.1.0/gems/railties-4.1.0/lib/rails/rack/logger.rb:  20:in `block in call'
…tivesupport-4.1.0/lib/active_support/tagged_logging.rb:  68:in `block in tagged'
…tivesupport-4.1.0/lib/active_support/tagged_logging.rb:  26:in `tagged'
…tivesupport-4.1.0/lib/active_support/tagged_logging.rb:  68:in `tagged'
…uby/2.1.0/gems/railties-4.1.0/lib/rails/rack/logger.rb:  20:in `call'
…ack-4.1.0/lib/action_dispatch/middleware/request_id.rb:  21:in `call'
…/ruby/2.1.0/gems/rack-1.5.2/lib/rack/methodoverride.rb:  21:in `call'
…/bundle/ruby/2.1.0/gems/rack-1.5.2/lib/rack/runtime.rb:  17:in `call'
…ctive_support/cache/strategy/local_cache_middleware.rb:  26:in `call'
…dle/ruby/2.1.0/gems/rack-zippy-1.2.1/lib/rack-zippy.rb:  39:in `call'
…/gems/font_assets-0.1.11/lib/font_assets/middleware.rb:  29:in `call'
…bundle/ruby/2.1.0/gems/rack-1.5.2/lib/rack/sendfile.rb: 112:in `call'
…actionpack-4.1.0/lib/action_dispatch/middleware/ssl.rb:  24:in `call'
…ruby/2.1.0/gems/rack-timeout-0.1.0/lib/rack/timeout.rb: 104:in `call'
…dle/ruby/2.1.0/gems/railties-4.1.0/lib/rails/engine.rb: 514:in `call'
…uby/2.1.0/gems/railties-4.1.0/lib/rails/application.rb: 144:in `call'
…/ruby/2.1.0/gems/puma-2.10.2/lib/puma/configuration.rb:  74:in `call'
…/bundle/ruby/2.1.0/gems/puma-2.10.2/lib/puma/server.rb: 492:in `handle_request'
…/bundle/ruby/2.1.0/gems/puma-2.10.2/lib/puma/server.rb: 363:in `process_client'
…/bundle/ruby/2.1.0/gems/puma-2.10.2/lib/puma/server.rb: 254:in `block in run'
…le/ruby/2.1.0/gems/puma-2.10.2/lib/puma/thread_pool.rb: 101:in `call'
…le/ruby/2.1.0/gems/puma-2.10.2/lib/puma/thread_pool.rb: 101:in `block in spawn_thread'

Also, none of the database queries were even calling the cache. Not sure if this is related, but any thoughts on why replication on heroku would be causing request timeouts?

Thanks!

[knightq]

Please, @eprothro, update also here (no caveat from verison 0.7.0)

[eprothro]

@knightq feel free to update that, all users have edit access, I believe.

[ricardovj]

Has this been actually solved? We're still seeing negative performance when enabling Octopus, enough to cause us to have disable it now :(
Our response times double as soon as we enable Octopus (even when pointing the shard to the same server), for example here we enabled it around 2:13PM:

[knagode]

I also have this same issue .. Is this intended to be solved?