StackOverflow2013

Note that there are some explanatory texts on larger screens.

plurals

PODiagnosing the cause of slow view rendering
text
Body
copied!<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 => %w(development test))) end module Goodsounds class Application < 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 => '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 => "localhost", :port => 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 => 5: default_render unless response_body 6: ret 7: end [2] pry(#<PagesController>)> 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 => 6: ret 7: end </code></pre>

Querying!

Guidance

An individual column

Larger individual text columns get their own page to allow for proper reading.

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload