83 votes

Abram avatar

Diagnostiquer la cause d'un rendu lent des vues

Demandé el 9 de Mars, 2013
Quand la question a-t-elle été
50712 affichage
Nombre de visites la question a
5 Réponses
Nombre de réponses aux questions
Résolu
Situation réelle de la question

Je ne sais pas exactement quand cela a commencé, mais quelque chose d'inhabituel se produit dans mon application (exécutée localement sur une machine de développement). Je vois soudainement des messages comme :

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)

Comme vous pouvez le constater, 3 secondes pour charger la page d'accueil (une page relativement simple) ... Il ne s'agit pas d'un rechargement en profondeur de la page, mais d'un simple clic sur le lien "home" à partir d'une autre page.

Je ne sais pas vraiment par où commencer, mais voici mon 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

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

EDIT:

OK, voici ce que je vois sur new relic. Cela ne m'aide pas vraiment. Des idées ?

enter image description here

enter image description here

Oh et ce que j'ai appris de la chronologie de Chrome :

Send Request - Details
Duration    0 (at 655ms)
Resource    localhost
Request Method  GET

Receive Response - Details
Duration    0.043ms (at 4.17s)
Resource    localhost
Status Code 200
MIME Type   text/html

Receive Data - Details
Duration    176.329ms (at 4.17s)
Self Time   7.037ms
CPU Time    176.329ms
Aggregated Time 061.194ms114.664ms0.471ms0
Resource    localhost
Encoded Data Length 303 Bytes
Used Heap Size  29.1MB (+5.7MB)

Finish Loading - Details
Duration    0 (at 4.35s)
Resource    localhost

D'ailleurs, j'ai désactivé la gem quiet_assets pour voir ce que je pouvais découvrir dans le terminal encore une fois rien d'utile :

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?ody=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)

D'ailleurs, suite à une suggestion sur reddit, j'ai précompilé les assets et j'ai lancé le serveur. Je vois des vitesses fantastiques :

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)

Ok, je ne suis pas sûr que cela soit utile ou non, mais le retard majeur se produit entre ces deux lignes de code dans la pile :

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

RETARD IMPORTANT

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
Demandé el 9 de Mars, 2013 par Abram

Réponses

Trop de publicités?

124voto

Abram avatar
Abram Points 3501

Ok, j'ai compris (enfin). Sans changer aucun de mes actifs réels, je vois maintenant que c'est le développement :

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)

Il s'avère que le retard est dû à config.assets.debug = true dans le fichier development.rb. En définissant ceci à false résout le problème.

Il semblerait que l'équipe de base de Rails ait débattu de la question suivante désactivation par défaut mais a décidé de ne pas le faire. A l'avenir, j'aimerais qu'ils mettent quelque chose dans la section commentaire de development.rb pour avertir les utilisateurs de la possibilité de retards importants.

Permettez-moi de suggérer ce qui suit :

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

Génial, ils m'ont entendu marmonner et rails mis à jour !

Répondu el 11 de Mars, 2013 par Abram (3501 Points )

34voto

antulik avatar
antulik Points 53

Le même problème est apparu pour moi dans rails 4.1+. La réponse d'Abram n'est que partiellement complète.

Vous pouvez quitter config.assets.debug = true mais devrait désactiver la fonction de vérification des nouveaux actifs

# 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

Solution avec config.assets.debug handicapés ne fonctionne que parce qu'il compile les actifs une seule fois et que les actifs sont vérifiés une seule fois. C'est à la vérification des actifs que l'on consacre le plus de temps.

Répondu el 21 de Octobre, 2014 par antulik (53 Points )

8voto

Sean O'Hara avatar
Sean O'Hara Points 560

Si vous venez de rails 3.2.13, notez qu'un certain nombre de personnes ont rencontré ce problème et que le retour à la version 3.2.12 semble le résoudre. Vous pouvez trouver plus d'informations ici sur github .

Dans mon cas, la désactivation de config.assets.debug a accéléré un peu les choses, mais le retour à la version 3.2.12 a fait chuter le temps de requête d'environ 4 secondes à environ 250 ms.

Répondu el 20 de Mars, 2013 par Sean O'Hara (560 Points )

2voto

RiPuk avatar
RiPuk Points 691

Jetez un coup d'œil à NewRelic.com - Il est payant, mais l'essai gratuit vous permettra de décortiquer entièrement votre application et de déterminer où se trouvent les goulets d'étranglement.

En dehors de New Relic, effectuez les vérifications habituelles, par exemple : quand a-t-il démarré ? Qu'avez-vous changé récemment ? Avez-vous mis à jour Rails et/ou d'autres gemmes ? Vérifiez et exécutez quelques versions antérieures à partir de votre contrôle de source et essayez de déterminer précisément quel commit a causé le problème.

Le problème se produit-il avec tous les navigateurs ? Essayez de lancer la visionneuse de chronologie de Chrome et vous pourrez voir si le navigateur se bloque sur un élément particulier de JavaScript.

Essayez également de basculer votre serveur web de développement local sur thin, le problème persiste-t-il ?

Bonne chance !

Répondu el 10 de Mars, 2013 par RiPuk (691 Points )

1voto

antrobot123 avatar
antrobot123 Points 1

Êtes-vous sous OSX et utilisez-vous .local ?

Si c'est le cas, je vais lancer le post que j'ai trouvé dans mes commentaires comme solution :
La contrainte de sous-domaine (Rails 3) rend le serveur local (thin) TELLEMENT LENT

Répondu el 10 de Mars, 2013 par antrobot123 (1 Points )

Questions en vedette

Top Tags

Dans notre réseau

Prograide.com

Prograide est une communauté de développeurs qui cherche à élargir la connaissance de la programmation au-delà de l'anglais.
Pour cela nous avons les plus grands doutes résolus en français et vous pouvez aussi poser vos propres questions ou résoudre celles des autres.

Powered by:

Yandex
X