Jbuilder Rails caching is slower

Question

I've tried to use caching with collections (with multiple solutions) the problem is that when ever I try caching the response become slower consider the following example of a collection that renders 2 partials for every item in it (around 25 item)

json.data do
  json.array! @organizations do |organization|
    json.partial! 'api/v1/organizations/organization', organization: organization
    json.partial! 'api/v1/organizations/links', organization: organization
  end
end

without caching the average response time is around ~38ms (on average)

now with caching

json.data do
  json.array! @organizations do |organization|
    json.cache! organization do
      json.partial! 'api/v1/organizations/organization', organization: organization
      json.partial! 'api/v1/organizations/links', organization: organization
    end
  end
end

with the jbuilder default caching and dalli store is properly installed and configured (I could verify that there was no cache miss)

the average response is around ~59ms (on average)

using the syntax found on Cache Digest

json.data do
  json.cache! @organizations do
    json.partial! 'api/v1/organizations/organization', collection: @organizations, as: :organization
    json.partial! 'api/v1/organizations/links', collection: @organizations, as: :organization
  end
end

the average response time is ~41ms (on average), and the response is different than the other responses

# Instead of getting
[{ data:{}, links:{} }, {{ data:{}, links:{} }]
# I get
[{ data:{}, data:{}, links:{}, links:{} }]

but the cache digest of the file is a very big string that will easily exceed the unix max file name length. this is the filename for example.

Cache write: jbuilder/organizations/5509f9284162643526000000-20150322012449497000000/organizations/5509e5924162643056020000-20150320223230684000000/organizations/550b54d8416264add2040000-20150321004501311000000/organizations/550e35704162640a98030000-20150322032224768000000/organizations/550e357b4162640a98050000-20150322032235260000000/organizations/550e35834162640a98080000-20150322032243162000000/organizations/550e35894162640a980a0000-20150322032249767000000/organizations/550e35904162640a980c0000-20150322032256464000000/organizations/550e35944162640a980e0000-20150322032300519000000/organizations/550e35984162640a98100000-20150322032304428000000/organizations/550e359c4162640a98120000-20150322032308542000000/organizations/550e35a04162640a98140000-20150322032312514000000/organizations/550e35a54162640a98160000-20150322032317066000000/organizations/550e35a84162640a98180000-20150322032320850000000/organizations/550e35ac4162640a981a0000-20150322032324716000000/organizations/550e35b04162640a981c0000-20150322032328643000000/organizations/550e35b54162640a981e0000-20150322032333651000000/organizations/550e35ba4162640a98200000-20150322032338114000000/organizations/550e35bd4162640a98220000-20150322032341889000000/organizations/550e35c14162640a98240000-20150322032345602000000/organizations/550e35c54162640a98260000-20150322032349739000000/3fcda1f9c320ab4284da56b4b2337cf5`

I've also tired Jbuilder Cache Multi

json.data do
  json.cache_collection! @organizations do |organization|
    json.partial! 'api/v1/organizations/organization', organization: organization
    json.partial! 'api/v1/organizations/links', organization: organization
  end
end

and the response was around ~57ms (on average)

plus with both jbuilder cache and multi I'm getting a lot of these in the logs

  Cache digest for app/views/api/v1/organizations/index.json.jbuilder: 3a51096b9c8da6a2cdb5b5a33ee58ea4
  Cache digest for app/views/api/v1/organizations/_organization.json.jbuilder: 4a1f1d49c90fdd867d88701f8a3fd6e1
  Cache digest for app/views/api/v1/organizations/_links.json.jbuilder: f2a881e125f95421d566edd571fdec73
  Cache digest for app/views/api/v1/organizations/index.json.jbuilder: 3a51096b9c8da6a2cdb5b5a33ee58ea4
  Cache digest for app/views/api/v1/organizations/_organization.json.jbuilder: 4a1f1d49c90fdd867d88701f8a3fd6e1
  Cache digest for app/views/api/v1/organizations/_links.json.jbuilder: f2a881e125f95421d566edd571fdec73
  Cache digest for app/views/api/v1/organizations/index.json.jbuilder: 3a51096b9c8da6a2cdb5b5a33ee58ea4
  Cache digest for app/views/api/v1/organizations/_organization.json.jbuilder: 4a1f1d49c90fdd867d88701f8a3fd6e1

so is it something wrong with my implementation or machine or local environment ? Rails 4.2.0, and Jbuilder 2.2.11

I also posted this issue to jbuilder #259

Vincent Woo Vincent Woo · Accepted Answer · 2015-03-31T00:59:44

To elaborate on my quote, as of right now (v2.2.12 of JBuilder), caching partials in JBuilder is only really worth it if one or both of the following are true:

You can skip AR queries (or computation) that are on average more expensive than accessing cache

Going to cache is usually a network call in the usual Rails stack, and while a DB query can be expensive, the cost of going over the network to get a serialized ActiveSupport blob, and then deserializing into a hash in Ruby is expensive and has to be done inside the Ruby VM. This is not good for performance.
The size of the JSON blob produced is small

As a corollary, if you have a small query, but produce a lot of JSON, you will quickly hit degraded performance as the blob is deserialized from an ActiveSupport blob, and then again on the way out to raw JSON. Remember, the cache does not store raw JSON, but a serialized intermediary format. This means, for every additional byte of JSON stored in the cache, you're going to have about 4 more bytes over the wire (from the serialized AS representation) and probably spend just as long deserializing as it would have taken to just compute the partial anyhow.

If you have an endpoint that produces a giant JSON blob, my recommendation is to just manually conditionally render the blob in the controller and cache it as a raw string in Rails.cache. The cost of recomputing all of your JSON now and then is probably less than going through JBuilder's cache machinery on every call.

Jbuilder Rails caching is slower

2 Answers