Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow when using layout: false #32

Open
axelson opened this issue Jan 28, 2016 · 4 comments
Open

Slow when using layout: false #32

axelson opened this issue Jan 28, 2016 · 4 comments

Comments

@axelson
Copy link

axelson commented Jan 28, 2016

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
Copy link
Contributor

antulik commented Aug 7, 2016

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
Copy link
Contributor

antulik commented Aug 7, 2016

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
Copy link

@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
Copy link

alexanderadam commented Mar 16, 2018

I hope this will be solved in 2018.

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

@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.

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

No branches or pull requests

4 participants