Slow when using layout: false

[axelson]

trafficstars

Trying to use this gem for caching a homepage that doesn't do much querying. However if I add layout: false then the speed drops dramatically.

Speeds:

• With no caching: 70ms
• With action caching: 6ms
• With action caching and layout: false: 200ms

So using action caching without caching the layout is significantly slower than doing no caching. Any ideas what could be causing this?

[antulik]

Faced the same problem. This is what I've found.

The performance bottleneck is at Dir#[] method. WAT? Exactly what I thought.

gem uses render_to_string method. If layout: true it renders layout as expected. BUT the way it does it is different here.

If you profile calls to Dir[]

class Dir
  def self.new_get *args
    puts "====================="
    puts args.inspect
    # puts caller(1)
    r = nil
    ms = Benchmark.ms {
      r = old_get *args
    }

    puts ms
    r
  end

  class << self
    alias_method :old_get, :[]
    alias_method :[], :new_get
  end
end

this is what i get

...
["/Users/anton/Dropbox/projects/rails5/app/pagelets/layouts/pagelets/panel{.en,}{.html,.text,.js,.css,.ics,.csv,.vcf,.png,.jpeg,.gif,.bmp,.tiff,.svg,.mpeg,.xml,.rss,.atom,.yaml,.multipart_form,.url_encoded_form,.json,.pdf,.zip,.gzip,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}"]
35.164861008524895
=====================
["/Users/anton/Dropbox/projects/rails5/app/pagelets/layouts/pagelets/panel{.en,}{.html,.text,.js,.css,.ics,.csv,.vcf,.png,.jpeg,.gif,.bmp,.tiff,.svg,.mpeg,.xml,.rss,.atom,.yaml,.multipart_form,.url_encoded_form,.json,.pdf,.zip,.gzip,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}"]
15.358514996478334
=====================
["/Users/anton/Dropbox/projects/rails5/app/pagelets/layouts/pagelets/panel{.en,}{.html,.text,.js,.css,.ics,.csv,.vcf,.png,.jpeg,.gif,.bmp,.tiff,.svg,.mpeg,.xml,.rss,.atom,.yaml,.multipart_form,.url_encoded_form,.json,.pdf,.zip,.gzip,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}"]
24.2648970161099
=====================
["/Users/anton/Dropbox/projects/rails5/app/views/layouts/pagelets/panel{.en,}{.html,.text,.js,.css,.ics,.csv,.vcf,.png,.jpeg,.gif,.bmp,.tiff,.svg,.mpeg,.xml,.rss,.atom,.yaml,.multipart_form,.url_encoded_form,.json,.pdf,.zip,.gzip,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}"]
30.61685399734415
...

That's ~30 milliseconds to each Dir#[] call. I have nested templates so that's 5+ calls for me. Insane.

To compare with normal call:

["/Users/anton/Dropbox/projects/rails5/lib/gem/pagelet_rails/app/views/layouts/tabs{.en,}{.html,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}"]
1.2392450007610023

As you can see the normal call takes 1millisecond. The difference is for some reason render_to_string adds crazy filters like

{.en,}{.html,.text,.js,.css,.ics,.csv,.vcf,.png,.jpeg,.gif,.bmp,.tiff,.svg,.mpeg,.xml,.rss,.atom,.yaml,.multipart_form,.url_encoded_form,.json,.pdf,.zip,.gzip,}{}{.raw,.erb,.html,.builder,.ruby,.coffee,.slim,.jbuilder,}

PS. this is tested on rails 5.0.0

Stack trace for the future

/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:229:in `find_template_paths'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:208:in `query'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:202:in `find_templates'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:129:in `block in find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:169:in `block in cached'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:67:in `cache'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:168:in `cached'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/template/resolver.rb:128:in `find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:79:in `block (2 levels) in _find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:75:in `each'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:75:in `block in _find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:74:in `each'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:74:in `_find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:54:in `find_all'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/path_set.rb:58:in `exists?'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/lookup_context.rb:135:in `exists?'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/abstract_renderer.rb:18:in `template_exists?'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:93:in `rescue in resolve_layout'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:85:in `resolve_layout'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:96:in `resolve_layout'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:76:in `find_layout'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:60:in `render_with_layout'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:52:in `render_template'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/template_renderer.rb:14:in `render'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/renderer.rb:42:in `render_template'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/renderer/renderer.rb:23:in `render'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/rendering.rb:103:in `_render_template'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionpack-5.0.0/lib/action_controller/metal/streaming.rb:217:in `_render_template'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionview-5.0.0/lib/action_view/rendering.rb:83:in `render_to_body'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionpack-5.0.0/lib/action_controller/metal/rendering.rb:52:in `render_to_body'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionpack-5.0.0/lib/action_controller/metal/renderers.rb:144:in `render_to_body'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionpack-5.0.0/lib/abstract_controller/rendering.rb:48:in `render_to_string'
/Users/anton/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/actionpack-5.0.0/lib/action_controller/metal/rendering.rb:41:in `render_to_string'

[antulik]

Continued... The question is why does it do that.

Rails searches for templates with specific format first and if nothing is found then all formats are checked. In my case I render html request in ajax requests.

Found a hack way to make it work

before_action do
  lookup_context.formats.unshift :html
end

pretty much tell that we are interested in html templates when doing lookup.

[jung-hunsoo]

@antulik Thanks, you got the right point. As you mentioned, it seems that lookup_context.formats are occurring a bottleneck. And I fortunately solved like this in the controller: before_action do { lookup_context.formats = [:html] } I tried using unshift first, but not improved. Hope this'll be solved in 2017.

[alexanderadam]

I hope this will be solved in 2018.

I just ran into the same issue now, just to find this two year old issue. :cry:

@antulik I know it's been a long time but did you remember how you found that bottleneck? I'm trying ruby-prof right now but I guess I have wrong parameters or something.

Update

Adding action caching even slows down things a lot before the actual rendering. It seems that the line

path_options = expand_option(controller, @cache_path)

causes the massive slow down. If I return yield earlier it is still fast. After that line it is slow again. @cache_path is a Proc. The key generation itself is fast but somehow it slows down later calculations.

UPDATE 2 The issue was in the cache key generation in my case.