☰

ビューのレンダリングが遅い原因の診断 質問する

tag-icon • tag-icon ruby-on-rails
ビューのレンダリングが遅い原因の診断 質問する

いつから始まったのかはわかりませんが、私のアプリ (開発マシンでローカルに実行) で異常なことが起こっています。突然、次のようなメッセージが表示されます。

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)

ご覧のとおり、ホームページ (比較的シンプルなページ) の読み込みには 3 秒かかります... ハード的なページの再読み込みではなく、別のページから「ホーム」リンクを再度クリックするだけです。

どこから始めればいいのかよく分かりませんが、これが私の application.rb です:

#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

...そして 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'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

編集：

OK、これが New Relic で見たものです。しかし、あまり役に立ちません。何かご意見はありますか?

ここに画像の説明を入力してください

ここに画像の説明を入力してください

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

ちなみに、ターミナルで何が見つかるかを確認するために quiet_assets gem を無効にしました。繰り返しますが、役に立ちません。

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)

ちなみに、reddit の提案に従って、アセットをプリコンパイルしてサーバーを実行しました。素晴らしい速度が見られました。

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)

これが役に立つかどうかはわかりませんが、スタック内の次の 2 行のコード間で大きな遅延が発生しています。

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

大幅な遅延

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

ベストアンサー1

はい、やっと分かりました。実際の資産を一切変更せずに、これが開発中であることがわかりました。

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)

遅延はconfig.assets.debug = truedevelopment.rb 内部で発生していたことが判明しました。これを に設定すると、false問題は解決します。

Railsコアチームが議論したようですこれをデフォルトでオフにする、しかし、そのアイデアは却下しました。将来的には、development.rb のコメント セクションに、大幅な遅延が発生する可能性があることをユーザーに知らせる内容が書かれることを期待しています。

以下のことを提案させていただきます。

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

よかった、彼らは私がつぶやいているのを聞いて更新されたレール！

おすすめ記事