Diagnosing the reason for slow viewing images

Question

I'm not sure when it started, but something unusual happens in my application (running locally on the development machine). Suddenly I see messages such as:

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) 

As you can see 3 seconds to load the home page (a relatively simple page) ... We are not talking about reloading hard pages. Just click the "home" link again from another page.

Not sure where to start here, but this is my .rb app:

 #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 

... and dev.rb:

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

EDIT:

OK, that’s what I see on the new relic. In fact, this does not help me. Any thoughts?

Oh, and what I learned from the chronology of Chrome:

 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 

By the way, I turned off the quiet_assets stone to find out what I can detect in the terminal .. again .. not useful:

 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) 

By the way, as suggested by reddit, I precompiled the assets and started the server. Seeing fantastic speeds:

 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) 

Not sure if this gives any help or not, but the main delay occurs between these two lines of code on the stack:

 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 

BASIC DELAY

 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 

Answer 1

Ok, I figured it out (finally). Without changing any of my actual assets, I now see that this is a development:

 Started GET "/" for 127.0.0.1 at 2013-03-11 23:14:33 +1300 Processing by PagesController#home as HTML Rendered pages/home.html.erb within layouts/application (1.3ms) 

It turned out that the delay was caused by config.assets.debug = true inside development.rb. Setting this parameter to false fixes the problem.

It seems that the core Rails team was discussing disabling this by default , but decided against this idea. In the future, I would like to see how they put something in the comments section of development.rb to ask users about the possibility of significant delays.

May I suggest the following:

 # Expands the lines which load the assets # May cause significant delays in view rendering 

Great, they heard me mumble and updated rails

Answer 2

The same problem appeared for me in rails 4.1+. Abram's answer is only partially completed.

You can leave config.assets.debug = true , but disable the function of checking new assets

 # Adds additional error checking when serving assets at runtime. # Checks for improperly declared sprockets dependencies. # Raises helpful error messages. config.assets.raise_runtime_errors = false 

A solution with config.assets.debug disabled config.assets.debug works because it compiles assets once and assets are checked once. Asset verification takes place where most of the time is spent.

Answer 3

If you came from rails 3.2.13, note that a group of people encountered this problem, and returning to 3.2.12 seems to resolve it. You can find more information here on github .

In my case, disabling config.assets.debug little faster, but returning to 3.2.12 reduced the request time from about 4 seconds to about 250 ms.

Answer 4

Take a look at NewRelic.com - it costs, but a free trial allows you to fully analyze your application and work where bottlenecks are.

In addition to New Relic, regular checks are performed, for example. when did it start? What have you recently changed? Have you updated Rails and / or any gems? Check and run several previous versions from your original control and try to perform the specific task that caused the problem.

Is there a problem with all browsers? Try running the Chrome History Viewer, and you can see if the browser is stuck in a specific piece of JavaScript.

Also try switching the local Dev web server to thin, does the problem persist?

Good luck

Answer 5

Are you on OSX and using .local?

If so, I am going to throw a post, which I found in my comments, as a solution:
Subdomain restriction (Rails 3) makes the local server (thin) SO SLOW