诊断视图渲染缓慢的原因
Posted
技术标签:
【中文标题】诊断视图渲染缓慢的原因【英文标题】：Diagnosing the cause of slow view rendering 【发布时间】：2013-03-09 23:17:26 【问题描述】：我不确定这是什么时候开始的，但我的应用程序中发生了一些不寻常的事情（在开发机器上本地运行）。突然我看到如下消息：
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
编辑：
好的，这是我在新遗物上看到的。虽然并没有真正帮助我。有什么想法吗？
哦，我从 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)
好的，不确定这是否提供任何帮助，但堆栈中这两行代码之间发生了主要延迟：
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
【问题讨论】：
这里只是一个猜测，但也许您正在加载我看到的未预编译的 javascript 或 css 负载。您是否有机会分享您的主视图和布局或至少在您认为问题出在哪里的 sn-ps？ 您是否生成了过多的 html？查看时间过去是页面大小的二次方。在评估视图模板时，在每次连接期间复制包含部分页面的字符串。 不，没有太多。也许 200 行 html？我如何为您量化尺寸。 发送请求和接收响应之间存在很大差距，但不幸的是 Chrome 时间线和 New Relic 没有告诉我是什么原因造成的。有没有办法强制服务器提供更多详细信息？ 嗯，您是否在 /etc/hosts 中定义了诸如“mysite.local”与“mysite.localhost”之类的内容？我通常会在开发时定义后者。出于某种原因，最近我决定以以前的方式“mysite.local”运行一个应用程序，每个页面加载需要 3-5 秒。改回“mysite.localhost”并恢复正常，加载几分之一秒。 【参考方案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)
原来延迟是由 development.rb 中的config.assets.debug = true 引起的。将此设置为 false 即可解决问题。
Rails 核心团队似乎对turning this off by default 进行了辩论，但最终决定反对这个想法。将来，我希望看到他们在 development.rb 的评论部分中添加一些内容，以提醒用户可能会出现重大延迟。
我可以建议以下几点：
# Expands the lines which load the assets
# May cause significant delays in view rendering
太好了，他们听到了我的嘀咕声和updated rails！
【讨论】：
如果适合你的项目，可以考虑使用turbolinks (github.com/rails/turbolinks)。这可能会缓解问题，因为资产只会在第一页加载时加载，并且您将保持资产调试的优势。 这绝对有帮助。一个小的修正：问题实际上是由 'config.assets.debug = true' 引起的，将其更改为 false 可以修复它。 @Abram 感谢分享。关于这个我挠了一阵子。 谢谢艾布拉姆。我有这个问题大约 6 个月... :) 这是我的确切问题 - CKE 正在扼杀我的渲染。第一个页面加载超过 60 秒。如此简单的修复。【参考方案2】：我在 rails 4.1+ 中也出现了同样的问题。艾布拉姆的回答只是部分完整。
您可以离开config.assets.debug = true，但应禁用新的资产验证功能
# 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
禁用config.assets.debug 的解决方案仅适用，因为它编译资产一次并且资产验证一次。资产验证是花费最多时间的地方。
【讨论】：
antulik，你能解决这个问题吗？我尝试了您的解决方案，但没有帮助我。我的应用程序曾经很快，但最近它的开发变得非常缓慢。有时需要 5-6 秒才能得到响应。超过 90% 的时间都在渲染应用程序/布局。 ***.com/questions/35006964/weird-logs-in-rails4 哦，我用上面的解决方案解决了。你的没有用，但不知道为什么。我在这里有一个问题。我的开发环境响应非常快，几天前突然变得超级慢。将 config.assets.debug 设置为 false 解决了我的问题，但你能猜到为什么这个问题会突然演变吗？我觉得这应该是一个缓慢的过程，所以在没有过渡的情况下遇到这个问题让我觉得我在我的代码中加入了一些东西。【参考方案3】：如果您来自 rails 3.2.13，请注意很多人都遇到过这个问题，并且恢复到 3.2.12 似乎可以解决它。您可以找到更多信息here on github。
在我的情况下，禁用 config.assets.debug 会加快一些速度，但恢复到 3.2.12 会将请求时间从大约 4 秒减少到大约 250 毫秒。
【讨论】：
谢谢！我的 0.2 秒页面请求在 3.2.13 时跃升至 15 秒。 这已在 Rails 3.2.14 中修复【参考方案4】：看看NewRelic.com - 它是收费的，但免费试用可以让您彻底剖析您的应用程序并找出瓶颈所在。
除了 New Relic 之外，还要进行常规检查，例如什么时候开始？你最近有什么变化？您是否升级了 Rails 和/或任何 gem？从您的源代码管理中检查并运行几个以前的版本，并尝试找出具体是哪个提交导致了问题。
所有浏览器都会出现此问题吗？尝试启动 Chrome 时间线查看器，您将能够查看浏览器是否卡在了特定的 JavaScript 片段上。
还可以尝试将本地开发网络服务器切换为瘦服务器，问题是否仍然存在？
祝你好运！
【讨论】：
不幸的是，我改变了一些东西，并将工作转移到了一台新的笔记本电脑上。所以，可能是一些东西......怀疑笔记本电脑升级是否做到了。一旦我确认这是否是一个宝石，我会回复你，但现在我不想关闭这个问题，以防有人能阐明我的情况。 您使用的是什么版本的 Rails？您是否也尝试过使用 Thin 作为本地开发 Web 服务器？你在使用源代码管理吗？ 嗨 Rails 3.2.13.rc1 ... Ruby 1.9.3 p392 ...我正在使用瘦。是的，我正在使用 git 和 bitbucket。 好的，我没有使用 3.2.13.rc1，但它是一个候选版本，所以切换到最后一个生产版本 (3.2.12) 以确保它不是那个版本。您是否回滚了您的提交历史以查看问题何时开始？我在上面的资产列表中注意到的一件事是你有很多你没有使用的东西，你应该清理它们（即当你只需要一个时你正在加载所有 gmaps4rails CSS，然后你出现用 selected.query 做某事两次）。 嘿，非常感谢您的帮助。明天晚上我会再看看这个，因为你提出了两个很好的建议。非常感谢，会尽快回复您。【参考方案5】：您是否使用 OSX 并通过 .local 提供服务？
如果是这样，我将在我的 cmets 中找到的帖子作为解决方案：Subdomain constraint (Rails 3) makes local server (thin) SO SLOW
【讨论】：
抱歉，使用 Linux Mint（基于 Ubuntu）以上是关于诊断视图渲染缓慢的原因的主要内容，如果未能解决你的问题，请参考以下文章