Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

This project is archived and is in readonly mode.

View rendering 9x slower than Rails 2.2.2

#1922

(In case the formatting fails here, a pleasant-to-look at version is at http://pastie.org/private/ervcyl... )

Despite the output logs being just about the exact same, Rails 2.3 RC1 is reporting as significantly slower than Rails 2.2.2 in development mode for my app. There is no visible reason for the slowdown in the logs, but the View rendering for 2.3 reports in as 9x slower than the View rendering in 2.2.2

These results are consistent across multiple page reloads.


Rails 2.3 RC1                                       Rails 2.2.2				
                                                    
Processing NodesController#blips (for 192           Processing NodesController#blips (for 192
                                                      Session ID: 41d43b6eb404659a1b7cf8b1627
  Parameters: {"action"=>"blips", "contro             Parameters: {"action"=>"blips", "contro
                                                      SQL (0.1ms)   SET SQL_AUTO_IS_NULL=0
  User Columns (2.4ms)   SHOW FIELDS FROM             User Columns (2.1ms)   SHOW FIELDS FROM
  List Columns (0.9ms)   SHOW FIELDS FROM             List Columns (1.1ms)   SHOW FIELDS FROM
  NodeClass Columns (1.4ms)   SHOW FIELDS             NodeClass Columns (1.3ms)   SHOW FIELDS
  NodeClass Load (0.6ms)   SELECT * FROM              NodeClass Load (0.6ms)   SELECT * FROM 
  Nodes::Movie Columns (1.6ms)   SHOW FIE             Nodes::Movie Columns (1.6ms)   SHOW FIE
  Nodes::Movie Load (122.5ms)   SELECT *              Nodes::Movie Load (129.7ms)   SELECT * 
  Nodes::Movie Load (115.8ms)   SELECT *              Nodes::Movie Load (116.9ms)   SELECT * 
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
  SQL (0.5ms)   SELECT count(*) AS count_             SQL (0.5ms)   SELECT count(*) AS count_
  Node Load (75.6ms)   SELECT * FROM `nod             Node Load (77.5ms)   SELECT * FROM `nod
  Node Columns (1.6ms)   SHOW FIELDS FROM             Node Columns (1.6ms)   SHOW FIELDS FROM
  CACHE (0.0ms)   SELECT count(*) AS coun             CACHE (0.0ms)   SELECT count(*) AS coun
  NodeClass Load (0.6ms)   SELECT * FROM              NodeClass Load (0.5ms)   SELECT * FROM 
  CACHE (0.0ms)   SELECT count(*) AS coun             CACHE (0.0ms)   SELECT count(*) AS coun
  Blip Columns (1.2ms)   SHOW FIELDS FROM             Blip Columns (1.0ms)   SHOW FIELDS FROM
  Image Columns (1.0ms)   SHOW FIELDS FRO             Image Columns (1.0ms)   SHOW FIELDS FRO
  Blip Load IDs For Limited Eager Loading             Blip Load IDs For Limited Eager Loading
  Blip Load Including Associations (4.7ms             Blip Load Including Associations (4.7ms
  SQL (113.3ms)   SELECT count(DISTINCT `             SQL (117.1ms)   SELECT count(DISTINCT `
  Blip Load (0.3ms)   SELECT * FROM `blip             Blip Load (0.4ms)   SELECT * FROM `blip
  Vote Load (0.4ms)   SELECT * FROM `vote             Vote Load (0.2ms)   SELECT * FROM `vote
Rendering template within layouts/applica           Rendering template within layouts/main
Rendering nodes/blips                               Rendering nodes/blips
Rendered home/_mini_login_block (0.9ms)             Rendered home/_mini_login_block (1.1ms)
Rendered ads/_ad_300 (0.2ms)                        Rendered ads/_ad_300 (0.1ms)
  Image Load (0.9ms)   SELECT * FROM `ima             Image Load (0.8ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.6ms)   SELECT * FROM `ima             Image Load (0.7ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
Rendered nodes/_titlelist (15.3ms)                  Rendered nodes/_titlelist (15.0ms)
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.4ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
  Image Load (0.4ms)   SELECT * FROM `ima             Image Load (0.3ms)   SELECT * FROM `ima
  CACHE (0.0ms)   SELECT * FROM `images`              CACHE (0.0ms)   SELECT * FROM `images` 
Rendered nodes/_titlelist (11.5ms)                  Rendered nodes/_titlelist (10.9ms)
  User Load (0.9ms)   SELECT * FROM `user             User Load (0.8ms)   SELECT * FROM `user
Rendered nodes/_action_menu (1.1ms)                 Rendered nodes/_action_menu (0.8ms)
  NodeClass Load (0.4ms)   SELECT * FROM              NodeClass Load (0.4ms)   SELECT * FROM 
Rendered blips/_blip (266.3ms)                      Rendered blips/_blip (17.7ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.4ms)                        Rendered blips/_blip (5.5ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.2ms)                        Rendered blips/_blip (5.2ms)
  User Load (0.6ms)   SELECT * FROM `user             User Load (0.7ms)   SELECT * FROM `user
Rendered nodes/_action_menu (0.8ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (6.1ms)                        Rendered blips/_blip (6.3ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.1ms)                        Rendered blips/_blip (5.4ms)
  User Load (0.5ms)   SELECT * FROM `user             User Load (0.5ms)   SELECT * FROM `user
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.9ms)                        Rendered blips/_blip (6.0ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
Rendered blips/_blip (4.7ms)                        Rendered blips/_blip (4.9ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.9ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.2ms)                        Rendered blips/_blip (5.5ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.2ms)                        Rendered blips/_blip (5.2ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
Rendered blips/_blip (4.6ms)                        Rendered blips/_blip (4.8ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.0ms)                        Rendered blips/_blip (5.0ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.1ms)                        Rendered blips/_blip (5.1ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.8ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.0ms)                        Rendered blips/_blip (5.0ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.1ms)                        Rendered blips/_blip (5.2ms)
  CACHE (0.0ms)   SELECT * FROM `users` W             CACHE (0.0ms)   SELECT * FROM `users` W
Rendered nodes/_action_menu (0.7ms)                 Rendered nodes/_action_menu (0.7ms)
  CACHE (0.0ms)   SELECT * FROM `node_cla             CACHE (0.0ms)   SELECT * FROM `node_cla
Rendered blips/_blip (5.1ms)                        Rendered blips/_blip (5.2ms)
Rendered layouts/_head (5.1ms)                      Rendered layouts/_head (7.1ms)
Rendered layouts/_footer (1.3ms)                    Rendered layouts/_footer (1.3ms)
Rendered layouts/_main_menu (5.4ms)                 Rendered layouts/_main_menu (157.5ms)
                                                    Cookie set: settings-anon=sort%3Dscore%26
Completed in 3854ms (View: 2775, DB: 608)           Completed in 1230ms (View: 314, DB: 629)

Reported by Chris Heald · February 9th, 2009 @ 04:35 PM

State: resolved
Milestone: 2.x
Assigned to: nobody
Importance: none

Activity

  1. Chris Heald
    Chris Heald

    Oh, I guess I should add that via the very scientific stopwatch test, Rails 2.3 is actually rendering more slowly - that is, this isn't solely an issue with the reporting.

    February 9th, 2009 @ 04:40 PM

  2. Andrew White
  3. Chris Heald
    Chris Heald

    Yup, that's the magic sauce. My view render time is back down to ~115ms on Rails 2.3, and the page render time is down accordingly. I'll add a note to your ticket.

    February 9th, 2009 @ 04:56 PM

  4. josh
    josh
    • State changed from new to resolved

    February 9th, 2009 @ 08:22 PM