rails: ActionView template finder can become really slow due to disk IO

As the number of view paths, template handlers and formats increases.

Caching ActionView::PathResolver#find_template_paths as follows sped the rendering of an API call (rabl/json) from 2500ms to 30ms once the cache was warmed up:

ActionView::PathResolver.class_eval do
  def find_template_paths(query)
    Rails.cache.fetch([:action_view_path_resolver_cache, query]) do
      Dir[query].reject { |filename|
        File.directory?(filename) ||
          # deals with case-insensitive file systems.
          !File.fnmatch(query, filename, File::FNM_EXTGLOB)
      }
    end
  end
end

Details

The app is Rails v4.1.11 / Ruby 2.2.1 / Spree 2-4-stable. I also noticed really slow performance for partial lookups relying on controller inheritance (e.g. render 'header' where _header.html is in app/views/application), I think it might be for the same reason.

I got this results on a Spree 2.4 app with Rails 4.1.11 calling this API endpoint during which #find_template_paths is called 137 times with queries as long as:

/Users/elia/.rvm/rubies/ruby-2.2.1/lib/ruby/gems/2.2.0/gems/kaminari-0.16.3/app/views/layouts/action_controller/base{.en,}{.json,}{.v10,.v9,.v8,.v7,.v6,.v5,.v4,.v3,.v2,.v1,}{}{.erb,.builder,.raw,.ruby,.prawn,.coffee,.opal,.haml,.rabl,.jbuilder,}

From what I saw not much has changed on rails@master wrt the path lookup, but I could be wrong. I agree that this can be regarded as a Spree issue but I believe that similar problems arise in many Rails apps.

just for completeness the logs of the two requests follow

Without the patch:

Started GET "/api/states.json?country_id=155" for 127.0.0.1 at 2015-07-01 23:49:58 +0200
Processing by Spree::Api::StatesController#index as JSON
  Parameters: {"country_id"=>"155"}
  Spree::User Load (0.5ms)  SELECT  "spree_users".* FROM "spree_users"  WHERE "spree_users"."deleted_at" IS NULL AND "spree_users"."spree_api_key" = '' LIMIT 1
  Spree::Country Load (0.3ms)  SELECT  "spree_countries".* FROM "spree_countries"  WHERE "spree_countries"."id" = $1 LIMIT 1  [["id", 155]]
  Spree::State Load (0.2ms)  SELECT  "spree_states".* FROM "spree_states"  WHERE "spree_states"."country_id" = $1  ORDER BY name DESC LIMIT 1  [["country_id", 155]]
  Spree::State Load (0.4ms)  SELECT "spree_states".* FROM "spree_states"  WHERE "spree_states"."country_id" = $1  ORDER BY name ASC  [["country_id", 155]]
  Rendered /Users/elia/.rvm/rubies/ruby-2.2.1/lib/ruby/gems/2.2.0/bundler/gems/spree-aa554d622f47/api/app/views/spree/api/states/index.v1.rabl (1.7ms)
Completed 200 OK in 2848ms (Views: 2829.6ms | ActiveRecord: 1.9ms)

With the patch:

Started GET "/api/states.json?country_id=155" for 127.0.0.1 at 2015-07-01 23:49:05 +0200
Processing by Spree::Api::StatesController#index as JSON
  Parameters: {"country_id"=>"155"}
  Spree::User Load (0.7ms)  SELECT  "spree_users".* FROM "spree_users"  WHERE "spree_users"."deleted_at" IS NULL AND "spree_users"."spree_api_key" = '' LIMIT 1
  Spree::Country Load (0.3ms)  SELECT  "spree_countries".* FROM "spree_countries"  WHERE "spree_countries"."id" = $1 LIMIT 1  [["id", 155]]
  Spree::State Load (0.2ms)  SELECT  "spree_states".* FROM "spree_states"  WHERE "spree_states"."country_id" = $1  ORDER BY name DESC LIMIT 1  [["country_id", 155]]
  Spree::State Load (0.4ms)  SELECT "spree_states".* FROM "spree_states"  WHERE "spree_states"."country_id" = $1  ORDER BY name ASC  [["country_id", 155]]
  Rendered /Users/elia/.rvm/rubies/ruby-2.2.1/lib/ruby/gems/2.2.0/bundler/gems/spree-aa554d622f47/api/app/views/spree/api/states/index.v1.rabl (1.8ms)
Completed 200 OK in 31ms (Views: 7.7ms | ActiveRecord: 2.0ms)

Solution (?)

The above patch of course is not good (even in concept) for development where views are added and modified regularly. A possible solution could be to keep the lookup dynamic just inside the app root and cache the paths coming from gems. That in turn could be an issue for people relying on the fact that views are reloaded even for gems in development (e.g. pleople using engines) but to me seems a good trade off anyway.

cc @tenderlove @masterkain

About this issue

Original URL
State: closed
Created 9 years ago
Reactions: 5
Comments: 30 (13 by maintainers)

Most upvoted comments

Just to add my 2 cents worth:

We have experienced exactly the problem you describe, and found that upgrading from ruby 2.1.* to 2.2.* or 2.3.* amplified the slow down by a factor of 3-4x ( mac os x ).

@layonferreira did some benchmarking around what we see as a performance regression in ruby

issue 10015

I also discovered this gem which looks to solve the issue we are seeing in Rails by caching the filenames and doing the search in memory

more_optimized_resolver presentation

Although it does not support case-insensitive files systems.

I would love to see the problem described fixed in rails, as it would make a huge difference to productivity and developer happiness when working with rails in development mode.

DangerDawson on Sep 1, 2016

This has been a pretty big problem in development for me for a couple years now. (I don’t totally understand why it became a bigger problem than it used to be; an app that previously was fine in dev with the number of partial tempaltes it loaded now is almost unusable in dev).

(I’m actually surprised this problem isn’t widespread. Maybe most people don’t try to use lots of partials?)

@wheeyls any chance of making an actual PR, which hopefully can be approved, to fix this for everyone?

jrochkind on Aug 20, 2018

I’m experiencing this in the test environment as well for system tests. A simple Rails.application.config.action_view.cache_template_loading = true fixes.

@tenderlove @rafaelfranca any reason this shouldn’t be true for the test environment? Seems like a no-brainer PR I could open…

bencrouse on Dec 19, 2017

I don’t know if this is directly related to this issue since I didn’t had the chance to dig into the ActionView code yet.

After upgrading a Rails 3.2 application to 4.2 and then 5.1 I noticed a huge performance drop in development environment when running Rails 4.2 or 5.1. It doesn’t happen in production.

This application makes use of several partials to render pages and rails log clearly show that actionview is taking 3s+ to load in some pages.

After verifying the differences between production and development environment, I found that the setting config.action_view.cache_template_loading is what causes the problem.

Enabling it in development drops the load time from 3000ms to less than 500ms. But having cache_template_loading enabled it not ok in development since I would have to restart the server whenever a template is changed.

It looks like Rails < 4 cached partials/templates within the same request but the newer versions doesn’t.

I added the following code in ApplicationController:

  prepend_before_action {
    ActionView::Resolver.caching = true
  }
  after_action {
    ActionView::Resolver.caching = false
  }

Then disabled config.action_view.cache_template_loading and restarted the server. I’m now getting the response times below 500ms while I still can make changes to views and test them without restarting the server.

This was tested on OS X 10.12.5 as well as in a docker container running phusion/passenger-ruby24:0.9.26 image.

fernandomm on Dec 19, 2017

This is probably related to this https://bugs.ruby-lang.org/issues/13167

fxgallego on Sep 26, 2017