title: Diagnosing the cause of slow view rendering
body: <p>I'm not sure when this started, but something unusual is happening in my app (run locally on a development machine). Suddenly I am seeing messages like:</p>
  
  <pre><code>Started GET "/" for 127.0.0.1 at 2013-03-10 12:10:24 +1300
  Processing by PagesController#home as HTML
    Rendered pages/home.html.erb within layouts/application (2.4ms)
  Completed 200 OK in 3242ms (Views: 3241.4ms | ActiveRecord: 0.0ms)
  </code></pre>
  
  <p>As you can see 3 seconds to load the home page (a relatively simple page) ... We're not talking a hard page reload .. just clicking on the "home" link again from another page.</p>
  
  <p>Not really sure where to start here, but this is my application.rb:</p>
  
  <pre><code>#config/boot.rb is loaded
  require File.expand_path('../boot', __FILE__)
  
  require 'rails/all'
  
  if defined?(Bundler)
    Bundler.require(*Rails.groups(:assets =&gt; %w(development test)))
  end
  
  module Goodsounds
    class Application &lt; Rails::Application
      config.encoding = "utf-8"
      config.filter_parameters += [:password]
      config.assets.initialize_on_precompile = false
      config.assets.enabled = true
      config.action_controller.assets_dir = "#{File.dirname(File.dirname(__FILE__))}/public"
      config.assets.version = '1.0'
      config.autoload_paths += Dir["#{Rails.root}/lib/modules"]
      config.assets.paths += Dir["#{Rails.root}/app/assets/fonts/*"]
      config.assets.precompile += %w( .svg .eot .woff .ttf ) 
    end
  end
  </code></pre>
  
  <p>...and dev.rb:</p>
  
  <pre><code>Goodsounds::Application.configure do
    # Settings specified here will take precedence over those in config/application.rb
      Paperclip.options[:command_path] = "/usr/bin/"
  
      config.action_mailer.default_url_options = { :host =&gt; 'localhost:3000' }
  
    config.action_mailer.raise_delivery_errors = true
  
    # set delivery method to :smtp, :sendmail or :test
    config.action_mailer.delivery_method = :smtp
  
    # these options are only needed if you choose smtp delivery
  
    config.action_mailer.smtp_settings = { :address =&gt; "localhost", :port =&gt; 1025 }
  
    # In the development environment your application's code is reloaded on
    # every request. This slows down response time but is perfect for development
    # since you don't have to restart the web server when you make code changes.
    config.cache_classes = false
  
    # Log error messages when you accidentally call methods on nil.
    config.whiny_nils = true
  
    # Show full error reports and disable caching
    config.consider_all_requests_local       = true
    config.action_controller.perform_caching = false
  
    # Print deprecation notices to the Rails logger
    config.active_support.deprecation = :log
  
    # Only use best-standards-support built into browsers
    config.action_dispatch.best_standards_support = :builtin
  
    # Raise exception on mass assignment protection for Active Record models
    config.active_re
  cord.mass_assignment_sanitizer = :strict
  
    # Log the query plan for queries taking more than this (works
    # with SQLite, MySQL, and PostgreSQL)
    config.active_record.auto_explain_threshold_in_seconds = 0.5
  
    # Do not compress assets
    config.assets.compress = false
  
    # Expands the lines which load the assets
    config.assets.debug = true
  end
  </code></pre>
  
  <p>EDIT: </p>
  
  <p>OK, Here is what I am seeing on new relic. Doesn't really help me though. Any thoughts?</p>
  
  <p><img src="https://i.stack.imgur.com/Q18sL.png" alt="enter image description here"></p>
  
  <p><img src="https://i.stack.imgur.com/Mog10.png" alt="enter image description here"></p>
  
  <p>Oh and what I learned from Chrome timeline:</p>
  
  <pre><code>Send Request - Details
  Duration    0 (at 655 ms)
  Resource    localhost
  Request Method  GET
  
  Receive Response - Details
  Duration    0.043 ms (at 4.17 s)
  Resource    localhost
  Status Code 200
  MIME Type   text/html
  
  Receive Data - Details
  Duration    176.329 ms (at 4.17 s)
  Self Time   7.037 ms
  CPU Time    176.329 ms
  Aggregated Time 061.194 ms114.664 ms0.471 ms0
  Resource    localhost
  Encoded Data Length 303 Bytes
  Used Heap Size  29.1 MB (+5.7 MB)
  
  Finish Loading - Details
  Duration    0 (at 4.35 s)
  Resource    localhost
  </code></pre>
  
  <p>By the way I disabled the quiet_assets gem to see what I could discover in the terminal.. again.. not helpful:</p>
  
  <pre><code>Started GET "/" for 127.0.0.1 at 2013-03-10 21:46:40 +1300
  Processing by PagesController#home as HTML
    Rendered pages/home.html.erb within layouts/application (43.4ms)
  Completed 200 OK in 3501ms (Views: 3480.9ms | ActiveRecord: 19.4ms)
  
  
  Started GET "/assets/dataTables/jquery.dataTables.bootstrap.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /dataTables/jquery.dataTables.bootstrap.css - 304 Not Modified (11ms)
  
  
  Started GET "/assets/chosen.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /chosen.css - 304 Not Modified (5ms)
  
  
  Started GET "/assets/select2.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /select2.css - 304 Not Modified (4ms)
  
  
  Started GET "/assets/autocomplete.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /autocomplete.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/branches.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /branches.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/bubbles.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bubbles.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/business_show.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /business_show.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/chunkyfive_font.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /chunkyfive_font.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/consumer_show.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /consumer_show.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/datatable_styling.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /datatable_styling.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/datepicker.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /datepicker.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/devise_links.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /devise_links.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/dispenser_show.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /dispenser_show.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/fonts.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /fonts.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/forms.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /forms.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/gmaps4rails.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/jquery-ui-1.10.0.custom.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jquery-ui-1.10.0.custom.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jumbotrons.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jumbotrons.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/layout.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /layout.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/open_sans.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /open_sans.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/popover.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /popover.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/reviews.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /reviews.css - 304 Not Modified (1ms)
  
  
  Started GET "/assets/spinner.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /spinner.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/style_show.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /style_show.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/style_show_reviews.css?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /style_show_reviews.css - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jquery.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jquery.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/jquery_ujs.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jquery_ujs.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/ui.custom.min.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /ui.custom.min.js - 304 Not Modified (1ms)
  
  
  Started GET "/assets/bootstrap-transition.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-transition.js - 304 Not Modified (5ms)
  
  
  Started GET "/assets/bootstrap-affix.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-affix.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-alert.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-alert.js - 304 Not Modified (4ms)
  
  
  Started GET "/assets/bootstrap-button.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-button.js - 304 Not Modified (5ms)
  
  
  Started GET "/assets/bootstrap-carousel.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-carousel.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-collapse.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-collapse.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-dropdown.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-dropdown.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-modal.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-modal.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-scrollspy.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-scrollspy.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-tab.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-tab.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap-tooltip.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-tooltip.js - 304 Not Modified (5ms)
  
  
  Started GET "/assets/bootstrap-popover.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-popover.js - 304 Not Modified (52ms)
  
  
  Started GET "/assets/bootstrap-typeahead.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap-typeahead.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/bootstrap.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /bootstrap.js - 304 Not Modified (13ms)
  
  
  Started GET "/assets/gmaps4rails/gmaps4rails.base.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails/gmaps4rails.base.js - 304 Not Modified (1ms)
  
  
  Started GET "/assets/gmaps4rails/gmaps4rails.bing.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails/gmaps4rails.bing.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/gmaps4rails/gmaps4rails.googlemaps.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails/gmaps4rails.googlemaps.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/gmaps4rails/gmaps4rails.mapquest.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails/gmaps4rails.mapquest.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/gmaps4rails/gmaps4rails.openlayers.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /gmaps4rails/gmaps4rails.openlayers.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jqueryplugins/addresspicker.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/addresspicker.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jqueryplugins/browser_detect.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/browser_detect.js - 304 Not Modified (3ms)
  
  
  Started GET "/assets/jqueryplugins/charts.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/charts.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jqueryplugins/jquery.alphanumeric.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/jquery.alphanumeric.js - 304 Not Modified (1ms)
  
  
  Started GET "/assets/jqueryplugins/jquery.formrestrict.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/jquery.formrestrict.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/jqueryplugins/jquery.lazyload.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/jquery.lazyload.js - 304 Not Modified (1ms)
  
  
  Started GET "/assets/jqueryplugins/raty.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /jqueryplugins/raty.js - 304 Not Modified (2ms)
  
  
  Started GET "/assets/dataTables/jquery.dataTables.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /dataTables/jquery.dataTables.js - 304 Not Modified (13ms)
  
  
  Started GET "/assets/dataTables/jquery.dataTables.bootstrap.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /dataTables/jquery.dataTables.bootstrap.js - 304 Not Modified (63ms)
  
  
  Started GET "/assets/lib/abstract-chosen.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /lib/abstract-chosen.js - 304 Not Modified (12ms)
  
  
  Started GET "/assets/lib/select-parser.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /lib/select-parser.js - 304 Not Modified (12ms)
  
  
  Started GET "/assets/chosen.jquery.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /chosen.jquery.js - 304 Not Modified (8ms)
  
  
  Started GET "/assets/chosen-jquery.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /chosen-jquery.js - 304 Not Modified (9ms)
  
  
  Started GET "/assets/select2.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /select2.js - 304 Not Modified (7ms)
  
  
  Started GET "/assets/highcharts.js?body=1" for 127.0.0.1 at 2013-03-10 21:46:44 +1300
  Served asset /highcharts.js - 304 Not Modified (1ms)
  </code></pre>
  
  <p>By the way, as per a suggestion on reddit I precompiled assets and ran the server. Seeing fantastic speeds:</p>
  
  <pre><code>Processing by PagesController#home as HTML
  Rendered pages/home.html.erb within layouts/application (1.1ms)
  Completed 200 OK in 6ms (Views: 5.4ms | ActiveRecord: 0.0ms)
  </code></pre>
  
  <p>Ok not sure this is providing any help or not but the major delay is happening between these two lines of code in the stack:</p>
  
  <pre><code>From: /home/funkdified/.rvm/gems/ruby-1.9.3-p392@goodsounds/gems/actionpack-3.2.13.rc1/lib/action_controller/metal/implicit_render.rb @ line 5 ActionController::ImplicitRender#send_action:
  
      3: def send_action(method, *args)
      4:   ret = super
   =&gt; 5:   default_render unless response_body
      6:   ret
      7: end
  
  [2] pry(#&lt;PagesController&gt;)&gt; next
  </code></pre>
  
  <p><strong>MAJOR DELAY</strong></p>
  
  <pre><code>From: /home/funkdified/.rvm/gems/ruby-1.9.3-p392@goodsounds/gems/actionpack-3.2.13.rc1/lib/action_controller/metal/implicit_render.rb @ line 6 ActionController::ImplicitRender#send_action:
  
      3: def send_action(method, *args)
      4:   ret = super
      5:   default_render unless response_body
   =&gt; 6:   ret
      7: end
  </code></pre>