Exception pages in development mode take upwards of 15-30 seconds to render, why is that?

Question

I am using Rails 3 beta 4 and for some reason I have each exception taking 15-30 seconds to show. Here is my trace:

Started GET "/something/something/approvals/new" for 127.0.0.1 at Thu Jun 24 21:17:12 -0400 2010
  SQL (1.8ms)  describe `approvals_users`
  SQL (24.6ms)  describe `clients_users`
  SQL (1.4ms)  describe `agencies_users`
  SQL (1.2ms)  describe `clients_users`
  SQL (1.2ms)  describe `approvals_users`
  SQL (1.7ms)  describe `permissions_users`
  Processing by ApprovalsController#new as HTML
  Parameters: {"project_id"=>"tricked", "client_id"=>"deez-nutz"}
  SQL (1.4ms)  describe `agencies_users`
  Agency Load (0.4ms)  SELECT `agencies`.* FROM `agencies` WHERE (`agencies`.`subdomain` = 'subdomain') LIMIT 1
  Plan Load (0.3ms)  SELECT `plans`.* FROM `plans` WHERE (`plans`.`id` = 3) LIMIT 1
  User Load (0.4ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
Completed   in 93ms

NoMethodError (undefined method `humanize' for nil:NilClass):
  app/models/approval.rb:38:in `state'
  app/models/approval.rb:38:in `state'
  app/controllers/approvals_controller.rb:10:in `new'
  app/controllers/approvals_controller.rb:10:in `new'

Rendered /Users/garrett/.bundle/ruby/1.8/bundler/gems/rails-07b08721a226ff01f983e61d99ab4da96e296c97-6682cce0386811ffe3e6d31fc025ede0936d86c3/actionpack/lib/action_dispatch/middleware/templates/rescues/_trace.erb (0.9ms)
  SQL (2.5ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
  SQL (0.9ms)  SHOW TABLES
Rendered /Users/garrett/.bundle/ruby/1.8/bundler/gems/rails-07b08721a226ff01f983e61d99ab4da96e296c97-6682cce0386811ffe3e6d31fc025ede0936d86c3/actionpack/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (21433.7ms)
Rendered /Users/garrett/.bundle/ruby/1.8/bundler/gems/rails-07b08721a226ff01f983e61d99ab4da96e296c97-6682cce0386811ffe3e6d31fc025ede0936d86c3/actionpack/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (21630.2ms)

If it helps at all, here is my Gemfile:

source 'http://gemcutter.org'

# Core
# gem 'rails', '3.0.0.beta4'
gem 'rails', :git => 'http://github.com/rails/rails.git'
gem 'sinatra'
gem 'mysql'
gem 'bundler'
gem 'memcache-client'
gem 'system_timer'
gem 'mime-types', :require => 'mime/types'
gem 'json'
gem 'haml', '~> 3.0.12'
gem 'state_machine'
gem 'bcrypt-ruby', :require => 'bcrypt'
gem 'juicer'
gem 'hoptoad_notifier'
gem 'braintree'
gem 'panda'

# Templating
gem 'liquid', '2.0.0'

# Users
gem 'warden'
gem 'ruby-openid', :require => 'openid'
gem 'canable'
gem 'devise'

# Paperclip
gem 'aws-s3', :require => 'aws/s3'
gem 'paperclip', :git => 'git://github.com/dewski/paperclip.git', :branch => 'rails3'
gem 'delayed_job', :git => 'git://github.com/dewski/delayed_job.git'

group :test do
  gem 'webrat'
  gem 'hpricot'
  gem 'mocha', :require => false
end

If I create a new Rails app, error pages show instantly. In the Rails source code, the method that has SHOW TABLES is structure_dump in schema_statements.rb. I searched my bundler directory for any sort of call to this method and it's not showing anything. What gives and how could this be caused to were SHOW TABLES is called over and over again and possibly making it so every method makes it pain to debug?

Answer 1

We've run into this problem at our company, and while we wait for an official Rails point release, have put together a hack. The key issue, as mentioned in the Lighthouse ticket linked in the other answer, seems to be that for some apps, request.env contains some objects whose #inspect output is HUGE (like, megabytes of text), and this output all gets put into the error page.

So here it is:

# development.rb

config.after_initialize do    
  module SmallInspect
    def inspect
      "<#{self.class.name} - tooooo long>"
    end
  end
  [ActionDispatch::RemoteIp::RemoteIpGetter, OmniAuth::Strategies::Facebook, ActionController::Base, Warden::Proxy].each do |klazz|
    klazz.send(:include, SmallInspect)
  end
end

The classes listed are the main culprits for us; yours will vary depending on your app.