Nesting cached Rails fragments slows down site by 300% in development: why?

Question

I am developing a Rails (4.1.14) site that uses Russian doll caching as follows:

home.html.erb:

<%= render partial: 'product/group', locals: {products: @products} %>`

product/_group.html.erb:

<% products.each do |product| %>
  <%= render partial: 'product/big', locals: {product: product} %>`
  <%= render partial: 'product/small', locals: {product: product} %>`
<% end %>

product/_big.html.erb:

<%= product.name %>`
<%= render partial: 'product/big_image', locals: {product: product} %>`

and so forth.

For some reason this page takes an extremely long time to load in development (12 seconds!).

When I inline all of the nested partials into the outermost one, page loading goes down 75%, to just 3 seconds.

This seems crazy, as it's the exact same content being rendered to the screen, and the caching on the outermost layer should make it irrelevant how I've styled what's inside.

So what on earth accounts for this slowdown?

The only thing I can think of is that it's Rails computing the cache digests for the inner layers. I suppose in production, Rails knows that the code won't change(?) and so it doesn't recurse down to get the digests?

Any ideas?

EDIT:

I have even tried setting the outermost (product/group) fragment to simply <% cache do %> so that all of the groups will render exactly the same. The site still takes like 6 seconds to load, and the logs show a bunch of activity:

  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (1.3ms)
  Rendered site/app/views/home/_product_group.html.erb (531.8ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (472.9ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (521.7ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (492.3ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (512.0ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (564.9ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.2ms)
  Rendered site/app/views/home/_product_group.html.erb (484.1ms)
  Cache digest for site/app/views/home/_product_big.html.erb: 336d5ebc5436534e61d16e63ddfca327
  Cache digest for site/app/views/shared/_discount.html.erb: 3c2aa3685fcb60f7d94e19d84263da77
  Cache digest for site/app/views/shared/_sale.html.erb: cb063c33aee387ae346ffe0d1679e7d9
  Cache digest for site/app/views/products/_image.html.erb: 50653bfa64782626a81e769fddc545ac
  Cache digest for site/app/views/home/_product_small.html.erb: f2c5bb4035a8b4261a2b6446ecad09ec
  Cache digest for site/app/views/home/_product_group.html.erb: 9c5de02f4004079ae10edd019083b659
Read fragment views/localhost:3000//9c5de02f4004079ae10edd019083b659 (0.1ms)
  Rendered site/app/views/home/_product_group.html.erb (526.2ms)

These are cached, so it should just be throwing in slabs of HTML straight from memory...in fact, the same slab of HTML again and again...yet each one results in all this logging activity. And each one takes 500ms! What's going on here?

Thanks!

Answer 1

You may be bottlenecked by your logger, especially if it is to STDOUT. If you have your server dumping the logging information to your terminal, it could be that is the culprit. (yeah I know it sounds crazy)

Try running it with logging shut off or written to a file rather than STDOUT. You can tail or less -F the file asynchronously.