Rails: Exception in View Freezes Rails

Created on 7 Jun 2011  路  116Comments  路  Source: rails/rails

Hi,

since I installed rails 3.1.0, when some bugs occur, Webrick freezes for a couple of minutes when some bugs occur (not all bugs, apparently the 500 ones).

My gemfile looks like this:

source 'http://rubygems.org'

gem "rails", "3.1.0.rc1"

Asset template engines

gem 'sass'
gem 'coffee-script'
gem 'uglifier'
gem 'jquery-rails'

gem "simple-navigation"
gem 'ranked-model' #, :git => '[email protected]:harvesthq/ranked-model.git'
gem 'formtastic'
gem 'validation_reflection'
gem "paperclip", "~> 2.3"
gem 'devise'
gem 'heroku'
gem "aws-s3"
gem "scoped_search"
gem "meta_search", :git => 'git://github.com/ernie/meta_search.git'
gem "kaminari"

group :production do
gem "pg", "~> 0.11.0"
gem 'therubyracer-heroku', '0.8.1.pre3'
gem 'exception_notification', :require => 'exception_notifier'
end

group :development, :test do
gem 'mysql2'
end

require 'csv'

Can anyone help me on this? Thanks,

Nicolas

asset pipeline
Source
picture ndemoreau

Most helpful comment

Out of curiosity, I've had a bit more of a look into this issue. The problem is internal to the Ruby interpreter; Rails isn't scrubbing this exception message as suspected by @tanelsuurhans seven months ago.

The root cause is name_err_mesg_to_str, which _always_ calls the inspect method of the object throwing the exception when constructing the message for a NameError or a NoMethodError. Which is pretty much what @tarmolehtpuu found in his first debugging session. This is the (1.9.2) code:

d = rb_protect(rb_inspect, obj, 0);
if (NIL_P(d) || RSTRING_LEN(d) > 65) {
  d = rb_any_to_s(obj);
}
desc = RSTRING_PTR(d);

...

if (desc && desc[0] != '#') {
  d = d ? rb_str_dup(d) : rb_str_new2(desc);
  rb_str_cat2(d, ":");
  rb_str_cat2(d, rb_obj_classname(obj));
}

args[0] = mesg;
args[1] = ptr[2];
args[2] = d;
mesg = rb_f_sprintf(NAME_ERR_MESG_COUNT, args);

That is:

  • Call inspect on the object that raised the exception
  • If the string returned is nil, or is more than 65 characters long, then call rb_any_to_s, which returns a string of the form #<CLASSNAME:ADDRESS>
  • If the string doesn't start with a #, then add the class name to the end of the string
  • Build the exception message via rb_f_sprintf

Now, when a NameError or NoMethodError is thrown from a view, any access of the message of the resulting exception object will cause name_err_mesg_to_str to be invoked, which in turn will call inspect on the object which raised the exception, very probably discarding the results.

The default implementation of inspect, as we now all know, can be resource hungry for large, complex objects. One perfectly reasonable fix, I think, would therefore be for name_err_mesg_to_str to call rb_inspect _only_ _if_ it had been overridden (that is, to never call the default implementation for an object). But that's as maybe. The fix for us is to ensure that we don't allow the default implementation of inspect to be called. Which is as simple as overriding it. Which is what the "RouteSet Hack" does.

Here's a simple test that replicates the issue in plain Ruby:

def test_slow_inspect
  require 'benchmark'
  SlowInspect.new.raise_name_error
rescue NameError => e
  time = Benchmark.realtime { puts e.message }
  puts "(done in #{(time*1000).to_i} ms)"
end

class SlowInspect
  def initialize(l=0)
    @foo = []
    10.times { @foo << ( l > 4 ? self : SlowInspect.new(l+1) ) }
  end
  def raise_name_error
    shazbut
  end
end

test_slow_inspect

class SlowInspect
  alias inspect to_s
end

test_slow_inspect

which prints the following on my machine:

undefined local variable or method `shazbut' for #<SlowInspect:0x105213990>
(done in 4593 ms)
undefined local variable or method `shazbut' for #<SlowInspect:0x10499fae8>
(done in 0 ms)

Note that the _result_ of calling e.message here is identical (well, apart from the address of the object); the only difference is that we're reducing the overhead of the call to inspect by overriding its default implementation.

In pure Ruby terms, "implement inspect for complex classes" is a good idiom. And, if you're bothering to do that, then "keep the length of the string returned by inspect no more than 65 characters" is a useful corollary, as it will yield more informative error messages for NameError and NoMethodError exceptions.

picture kranzky on 21 Feb 2012
👍3

All 116 comments

I've experienced this as well... It doesn't seem to happen consistently though.

My gems:

gem 'rails', '3.1.0.rc1'
gem 'sqlite3'
gem 'mysql2'
gem 'json'
gem 'sass'
gem 'coffee-script'
gem 'uglifier'
gem 'jquery-rails'
gem 'capistrano'
gem 'compass', :require=>false
gem 'hoptoad_notifier'
gem 'devise'
gem 'cancan'
gem 'simple_form', :git=>"git://github.com/plataformatec/simple_form.git", :branch=>"master"
gem 'nifty-generators'
gem "paperclip", "~> 2.3"
gem 'inherited_resources'
gem "nested_form", :git => "git://github.com/ak/nested_form.git"
gem "acts_as_list"
gem 'kaminari'
gem 'thinking-sphinx', :git => "git://github.com/freelancing-god/thinking-sphinx.git", :branch => 'rails3'
gem 'sprite-factory'
gem 'rmagick'

markhurlburt picture markhurlburt on 7 Jun 2011

I agree. It's unconsistent. The problem is the same with Unicorn or Mongrel. When I look at the activity monitor, I can clearly see the "ruby" process using more and more ram memory, until total freeze when this happen. I still don't know the reason. What I'm sure is that the bug has nothing to do with an infinite loop or somtehing like that.

Strange behaviour as well is the fact that, when it doesn't freeze, instead of being redirected to a page with details about the error, I'm redirected to the 500.html page, like in production.

ndemoreau picture ndemoreau on 7 Jun 2011

@ndemoreau, are you using the Rails HTTP streaming by any chance?

utkarshkukreti picture utkarshkukreti on 8 Jun 2011

Correct. I disabled it and now, i'm not redirected to the 500.html page anymore and the freeze doesn't seem to happen anymore (I did very few tests).

Thanks! I keep you posted.

Nicolas.

On 8 juin 2011, at 10:57, utkarshkukreti wrote:

@ndemoreau, are you using the Rails HTTP streaming by any chance?

Reply to this email directly or view it on GitHub:
https://github.com/rails/rails/issues/1525#comment_1325420

ndemoreau picture ndemoreau on 8 Jun 2011

Just to let you know that it seems to be more stable but it is still not totally fixed yet. It just freezed when I mistyped an input on a simple_form form: <%= input.tel ... %>

ndemoreau picture ndemoreau on 8 Jun 2011

+1 on this.

I am using the edge Rails and when the error is raised in the view then Rails freezes (eats more and more CPU and memory). When I hit Ctrl-C in console then the error is outputted to the console. I am on Mac OS X Snow Leo and using the latest Ruby 1.9.2. My server is Mongrel. I've also attached some 'dtruss' output here: https://gist.github.com/1016728

andreychernih picture andreychernih on 9 Jun 2011

This issue is really annoying, the memory usage grows so fast it becomes quite difficult to even switch to a terminal window to kill the process. I tried to find the source of the problem, but I'm not that familiar with Rails codebase and ruby-prof isn't able to complete the dump file once things blow up (waited a good 15 minutes with my rsize growing to ~4GB).

Hoping that this will help a little bit in solving the problem then here's what I tried and figured out.

First create a view that uses assets and renders OK (without errors):

= stylesheet_link_tag :admin
= javascript_include_tag :admin

This should be OK

Then create a view that has an error like the one below:

= this_should_blow_up

Environment: OS X Snow Leopard, 1.9.2, Thin, Rails 3.1.0 RC4.

tarmolehtpuu picture tarmolehtpuu on 5 Jul 2011

Yeah, this does make development (porting to 3.1) tricky. I've found that if I CTRL-C the server sometimes I do get an error message output, which helps me track down that one problem to inch forward. Not fun.

I am also seeing this with Passenger.

I am using RoR 3.1 RC 4

adamjack picture adamjack on 7 Jul 2011

Is this still an issue using rails from git 3-1-stable branch?

spastorino picture spastorino on 12 Jul 2011

Yeah, still reproducible, but now better (6-7 secs until I see the error in browser). Workaround is to put this code in 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
andreychernih picture andreychernih on 21 Jul 2011

Can you share with us an application where we can try to reproduce the error?

spastorino picture spastorino on 21 Jul 2011

Unfortunately, I can not share it with you because it's proprietary. I simply have HomeController#index action. In index.html.erb I place a call:

<% non_existing_method %>

It takes 7 secs to render the error in browser and console without the workaround code. And it takes 2 secs to render the error with workaround code. My Gemfile:

source 'http://rubygems.org'

gem 'rake', '0.8.7'
gem 'rails', :git => 'https://github.com/rails/rails.git', :branch => '3-1-stable'
gem 'mysql', '2.8.1'
gem 'jquery-rails', '1.0.7'
gem 'devise', :git => 'https://github.com/plataformatec/devise.git'
gem 'mini_magick', :git => 'https://github.com/AndreyChernyh/mini_magick.git' # , :path => '~/projects/gems/mini_magick'
gem 'fog', :git => 'https://github.com/AndreyChernyh/fog.git'
gem 'carrierwave', :git => 'https://github.com/AndreyChernyh/carrierwave.git'
gem 'faraday', '0.6.1'
gem 'oa-oauth', '0.2.6', :require => 'omniauth/oauth'
gem 'oa-openid', '0.2.6', :require => 'omniauth/openid'
gem 'oauth', '~> 0.4.0'
gem 'kaminari', '0.12.4'
gem 'exception_notification_rails3', :require => 'exception_notifier'
# TODO check if the official gem updated
gem 'grouped_validations', :git => 'https://github.com/adzap/grouped_validations.git'
gem 'memcache-client', '1.8.5'
gem 'acts-as-taggable-on', :git => 'https://github.com/denisj/acts-as-taggable-on.git'
gem 'gravtastic', '3.1.0'
gem 'twitter', '1.4.1'
gem 'fbgraph', '1.8.0'
gem 'thinking-sphinx', '2.0.5'
gem 'ts-datetime-delta', '1.0.2', :require => 'thinking_sphinx/deltas/datetime_delta'
gem 'sass-rails'
gem 'whenever', '0.6.7', :require => false
gem 'newrelic_rpm', '3.1.1.beta1'
gem 'configatron', '2.8.0'
gem 'delayed_job', '2.1.4'
gem 'yui-compressor', '0.9.6'
#gem 'mailman', '0.4.0'

# admin
gem 'meta_search', '>= 1.1.0.pre'
gem 'activeadmin', :git => 'https://github.com/gregbell/active_admin.git'

# caching
gem 'hiredis', '~> 0.3.1'
gem 'redis', '~> 2.2.0', :require => ["redis/connection/hiredis", "redis"]
gem 'redis-store', '1.0.0.rc1'

group :development, :test do
  gem 'mongrel'
  gem 'rspec-rails', '2.6.1.beta1'
  gem 'ruby-prof'
end

group :test do
  gem 'factory_girl_rails', '1.0.1'
  gem 'shoulda-matchers', :git => 'https://github.com/thoughtbot/shoulda-matchers.git'
  gem 'autotest-rails', '4.1.0'
  gem 'capybara', :git => 'git://github.com/jnicklas/capybara.git'
  gem 'timecop', '0.3.5'
  gem 'launchy'
end

group :production, :staging do
  gem 'unicorn'
end
andreychernih picture andreychernih on 21 Jul 2011

I'm on master and I've still got this. It happens every time you call a non-existent method as @AndreyChernyh said.

Want me to try on the stable branch or should master have fixed it if stable has?

This app is also proprietary and it's massive, but I'm happy to provide any traces or info that might be useful.

My Gemfile looks like this:

source 'http://rubygems.org'

gem 'rails', :git => "git://github.com/rails/rails.git"

gem 'mysql2'
gem 'rubyzip2'
gem 'libxml-ruby'
gem 'will_paginate', :git => "git://github.com/JackDanger/will_paginate.git" #"git://github.com/mislav/will_paginate.git"
gem 'cocaine'
gem 'paperclip', :git => "git://github.com/ihid/paperclip.git", :branch => "delayed_fog"
gem 'json'
#gem 'rmagick', "2.13.1"
gem 'hpricot'
gem 'ruby-openid'
gem 'exceptional'
gem 'memcache-client'
gem 'haml', :git => "git://github.com/ihid/haml.git"
gem 'sass-rails', :git => "git://github.com/rails/sass-rails.git"
#gem 'sass', :git => "git://github.com/nex3/sass.git"
gem 'bourbon', :git => "git://github.com/ihid/bourbon.git"
gem 'coffee-script'
gem 'uglifier'
gem 'jquery-rails'
gem 'pdfkit', "0.5.1"
gem 'aws-s3', :require => "aws/s3"
gem 'fog'
gem 'amazon-ec2'
gem 'oink'
gem 'foreigner', :git => 'git://github.com/matthuhiggins/foreigner.git'
gem 'bson_ext'
gem 'super_sti', :git => "git://github.com/ihid/super_sti.git"
gem 'belongs_to_enum', :git => "git://github.com/ihid/belongs_to_enum.git"
gem 'activemerchant', :git => "git://github.com/ihid/active_merchant.git"

group :test do
    gem 'ruby-debug19', :require => 'ruby-debug'
    gem 'rspec-rails'
    gem 'autotest'
    gem 'webrat'
end

group :development do
  #gem 'rails-dev-boost', :git => 'git://github.com/thedarkone/rails-dev-boost.git', :require => 'rails_development_boost'
end

group :production do 
  gem 'thinking-sphinx',
    :git     => 'git://github.com/freelancing-god/thinking-sphinx.git',
    :branch  => 'rails3',
    :require => 'thinking_sphinx'
end
iHiD picture iHiD on 21 Jul 2011

This is the output I get if I kill the server with CTRL-C (the ^C are me holding down CTRL-C as my computer is totally unresponsive by this point). 

^C^C^C^C^C^C^C^C[2011-07-21 16:29:00] ERROR NoMethodError: undefined method `shutdown' for nil:NilClass
    /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/activesupport/lib/active_support/whiny_nil.rb:48:in `method_missing'
^C^C^C^C^C^C/Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/activesupport/lib/active_support/whiny_nil.rb:48:in `method_missing': undefined method `shutdown' for nil:NilClass (NoMethodError)
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/handler/webrick.rb:24:in `shutdown'
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/server.rb:259:in `block in start'
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/server.rb:320:in `call'
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/server.rb:320:in `block in write_pid'
    from script/rails:in `call'
^C^C^C^C^C^C^C^C^C^C^C

Started GET "/publications/1" for 127.0.0.1 at 2011-07-21 16:28:29 +0100
Processing by PublicationsController#show as HTML
  Parameters: {"id"=>"1"}
  User Load (0.5ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 2 LIMIT 1
  Publication Load (0.2ms)  SELECT `publications`.* FROM `publications` WHERE `publications`.`id` = 1 LIMIT 1
Compiled ~/.rvm/gems/ruby-1.9.2-p180/gems/jquery-rails-1.0.12/vendor/assets/javascripts/jquery.js  (0ms)  (pid 6640)
Compiled ~/.rvm/gems/ruby-1.9.2-p180/gems/jquery-rails-1.0.12/vendor/assets/javascripts/jquery_ujs.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.ui.min.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.tools.min.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.tokeninput.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.jcrop.min.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.iframe-transport.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/jquery.fileupload.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/general.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/meducation.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/ui.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/users.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/widgets.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/exam_room/practice/exams.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/exam_room/practice/questions.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/exam_room/practice/mcqs.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/exam_room/practice/sbas.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/publications.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/ecommerce.js.coffee  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/javascripts/application.js  (0ms)  (pid 6640)
Compiled ~/Projects/Work/meducation/app/assets/stylesheets/application.css.scss  (0ms)  (pid 6640)
  Rendered publications/show.html.haml within layouts/application (30347.5ms)
Completed 500 Internal Server Error in 30794ms

ActionView::Template::Error (undefined local variable or method `asdwqe' for #<#<Class:0x0000010c28b330>:0x0000010c2872f8>):
    69:         
    70:         #publication_container    
    71:             
    72:             -non_existant.each do |i|
    73:                 -x
    74: 
    75: 
  app/views/publications/show.html.haml:72:in `_app_views_publications_show_html_haml___2654011636592586608_2249469060'

  Rendered /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/templates/rescues/_trace.erb (120.3ms)
  Rendered /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (3.9ms)
  Rendered /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/templates/rescues/template_error.erb within rescues/layout (210.9ms)
^C^C^C^C^C^C/Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/activesupport/lib/active_support/whiny_nil.rb:48:in `method_missing': undefined method `shutdown' for nil:NilClass (NoMethodError)
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/handler/webrick.rb:24:in `shutdown'
    from /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/server.rb:259:in `block in start'
    from script/rails:in `call'
^C^C
iHiD picture iHiD on 21 Jul 2011

Digging into this deeper, I'm also sporadically getting the following. It may or may not be related.

(Update: now I've applied @AndreyChernyh's hack, I get this ever time a page fails.)

Error during failsafe response: incompatible character encodings: UTF-8 and ASCII-8BIT
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:132:in `block in log_error'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/activesupport/lib/active_support/deprecation/reporting.rb:20:in `silence'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:130:in `log_error'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:65:in `render_exception'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:60:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/railties/lib/rails/rack/logger.rb:13:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/methodoverride.rb:24:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/runtime.rb:17:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/activesupport/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/lock.rb:15:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/actionpack/lib/action_dispatch/middleware/static.rb:53:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/railties/lib/rails/engine.rb:454:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/railties/lib/rails/rack/content_length.rb:16:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/bundler/gems/rails-993d0f6477c6/railties/lib/rails/rack/log_tailer.rb:14:in `call'
  /Users/iHiD/.rvm/gems/ruby-1.9.2-p180/gems/rack-1.3.1/lib/rack/handler/webrick.rb:59:in `service'
  /Users/iHiD/.rvm/rubies/ruby-1.9.2-p180/lib/ruby/1.9.1/webrick/httpserver.rb:111:in `service'
  /Users/iHiD/.rvm/rubies/ruby-1.9.2-p180/lib/ruby/1.9.1/webrick/httpserver.rb:70:in `run'
  /Users/iHiD/.rvm/rubies/ruby-1.9.2-p180/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'
iHiD picture iHiD on 21 Jul 2011

I had this problem on an app I no longer work on, but we worked around with the #inspect monkey patch provided above.

This issue was potentially made harder to reproduce by 5b8801442ea02fc942ae0ee8ef81a9120525f5f0 that filters out most of the rack stuff from the env dump.

It doesn't fix the root problems though, of which there are two:

  1. #inspect on an ActionController::Base instance is 33K (!!) on a blank rails app. This is totally unhelpful. The opposite extreme (only show the class name) would be more useful and not misleading.
  2. The error page blindly renders the inspect of everything in the session and a lot of stuff in the environment. This is potentially megabytes of data, most of which is hidden by default, and given it's volume likely not interesting in the majority of cases. While generating the inspect output can potentially take a long time (see point 1), changing debug_hash in actionpack/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb to truncate the output to an arbitrary length (100 chars?) seems reasonable to me.

Happy to provide a patch for either or both of these suggestions @spastorino if you agree.

xaviershay picture xaviershay on 23 Jul 2011

Are you guys aware of why this is only happening when the error is a missing method? Parse errors and general exceptions are being handled fine. Is a different template rendered for this etc?

Could we maybe mimic the other exception behaviours here?

Excuse my questions rather than solutions - I don't know this bit of the codebase at all and am too bogged down with deadlines to explore it right now. Sorry.

iHiD picture iHiD on 23 Jul 2011

I experience the issue with unicorn as well as webrick. My trick is to spot it before the memory monster goes past the 1GB.. from years of CounterStrike I tend to have a good reaction time.. ha ha..

Anyway it only happens on method_missing errors for me, typical typo errors. When making a new app it doesnt seem to happen in webrick or unicorn. I only tested this for a few minutes.

Maybe important is also the information that it doesnt only happen on the view layer. I also had this happen in a model, 100% reproducible. Unfortunately I deleted that bit of code :/ (I know Im a dummy...) I will post some code if i can reproduce it again.

Stefano1990 picture Stefano1990 on 25 Jul 2011

I've managed to capture a couple stack traces - http://pastie.org/2268985

tarmolehtpuu picture tarmolehtpuu on 25 Jul 2011

When monkey patching rack-mount/lib/rack/mount/route.rb inspect to not call @app.inspect at least the problem goes away, along with some debug info :(

tarmolehtpuu picture tarmolehtpuu on 25 Jul 2011

@xaviershay I'm happy with that. Can you put together a patch?

tenderlove picture tenderlove on 25 Jul 2011

Seems that I managed to fix this (at least I am not able to reproduce this issue anymore).
I created a pull request with the change: https://github.com/rails/rails/pull/2264

It seems that when a Template:Error is raised from rendering the actual view, the layout rendering fails with calling .html_safe on nil content. This in turn raises another error, which then causes the whole loop to repeat until the host machine runs out of RAM.

tanelsuurhans picture tanelsuurhans on 25 Jul 2011

Great find @tanelsuurhans. I'm still going to put together a patch for my suggestions as I still think they're worthwhile additions.

xaviershay picture xaviershay on 25 Jul 2011

Pull request for shorter inspect output for Rails::Engine (the @app.inspect culprit from above), and AbstractController. Adds ActiveSupport::ShortInspect so others can use it also: https://github.com/rails/rails/pull/2269

Probably not going to get around to the #debug_hash changes I suggested just at the moment. /cc @tenderlove

xaviershay picture xaviershay on 26 Jul 2011

I debugged this problem some more, it seems to happen in C code - action_view/template/error.rb#initialize never returns, more accurately the call to NameError.message never returns: super(original_exception.message).

I've tried this also with JRuby (1.6.3) and everything works, the following is the result from original_exception.message:

undefined local variable or method `foo' for #<#Class:0x174cff77f:0x2e20a282>

For some reason 1.9.2-p0 and 1.9.2-p290 are unable to call name_err_mesg_to_str without going into an endless loop and concating to a huge string buffer. I've captured a couple of C level stack traces with GDB also and I think it looks like the string is already over 8 MB.

What I suspect is that while name error is looping instance variables there's some sort of circular reference or edge case that causes it to keep looping endlessly (no recursion since stack overflow doesn't happen).

I also pastied the C stack traces: http://pastie.org/2274529 and http://pastie.org/2274530

I'll try to go through the C code a bit more when I get the chance, meanwhile hope that this helps a bit in finding the cause of the problem.

tarmolehtpuu picture tarmolehtpuu on 26 Jul 2011

@tarmolehtpuu can you consistently reproduce the error? If so, can you push an app to github that I can use to repro?

tenderlove picture tenderlove on 26 Jul 2011

I got into this loop too since 3.1.0.rc1.
Now with rc5 using passenger 3.0.3 on ruby 1.8.7 it's not really the same case, the waiting is long, but not endless like in rc1-4 for me.

On rc4, I had to kill the process and relaunch passenger.

Mainly caused by "undefined method" errors, I think when the app crashes for something else, like syntax err, it is OK. (sorry if this is already known.)

3.1.0.rc1+
ruby 1.8.7 (2010-01-10 patchlevel 249) [universal-darwin11.0] && ruby 1.8.7 EE 2011.3
passenger 3.0.3

daliborfilus picture daliborfilus on 26 Jul 2011

@tenderlove, I'm able to reproduce it, but as usual the app is proprietary and I can't share it I think (I'll have to check). I've been trying to reproduce this with a fresh application, no luck so far. I'll try some more over the weekend.

tarmolehtpuu picture tarmolehtpuu on 28 Jul 2011

I've tried assets, haml and couple other things I could think of that might be causing it, no luck yet. In case anyone would like to try to reproduce this bug in a fresh app then here's a good starting point: https://github.com/perfectline/name-error-inspect

Gemfile and Gemfile.lock are both from an app where this bug appears, just something is missing. Might be worth a try to add some AR usage and maybe bit more exotic stuff like default scopes etc...

tarmolehtpuu picture tarmolehtpuu on 28 Jul 2011

OK - This is a slightly different observation which may or may not be related to any of this. When the server starts absorbing memory and I kill it, the shutdown method gets itself into an endless loop.

In webrick.rb in the rack gem is the following
```def self.shutdown
@server.shutdown
@server = nil
end

``````

Because @server is nil, shutdown gets called on nil, and for some reason this causes massive recursion.

When I change this to the following, I can kill the server cleanly.
@server.shutdown if @server.respond_to?(:shutdown)

In the last 48hrs, this issue has stopped affecting me altogether. Whether it's down to this, or something totally different, I don't know. I've made lots of commits in the last few days, but the only infrastructure ones are that I've moved to 3-1-stable (from master) and to the sass-rails 3-1 branch (from master).

I will try further to backtrace my steps and see what's gone right, but I thought I'd mention this in case it's a pointer in a helpful direction.
``````

iHiD picture iHiD on 29 Jul 2011

I'm pretty sure we're seeing this happen on Heroku (Bamboo REE 1.8.7 using Thin). We get locked dynos and I'm guessing this is the cultprit (as we see this problem all the time in dev mode).

It seems fairly in-determinate so it does seem like a race condition as suggested above.

If it is happening in production, I'd say it's a big problem.

matpowel picture matpowel on 31 Jul 2011

I must confess that this thread totally confuses me! :-)

I think there are two similar nicks and alot of info going on. I'll try to summarize.

@AndreyChernyh came up with the #inspect monkey patch, which helps some people but not others. It doesn't solve the problem for us.

@xaviershay 's found a few similar things, his patch appears to do the same thing as the Andrey's?

It sounded like @tarmolehtpuu had a sweet fix but when following the link to the pull request he closed it because it doesn't fix the issue.

(BTW I think this is because I've found that sometimes I hit the error and then restart the server and the same code does NOT reproduce the error, although other times it seems consistant, so it's constantly inconsistant :-)

@ihid seems to have solved the problem of not being able to ctrl-C properly but not the actual bug?

Some more observations:

  • Everyone who is hitting the problem seem to have larger, commercial, production apps (at least, lots of gems and they can't share their app, like us).. so perhaps it's memory or resource related?
  • Info seems to be drying up, which is worrying because I'm sure we're seeing this in production. Locking up our dynos and rendering our app unresponsive. Of course you could argue that we shouldn't have any "method missings" in production but it's not our release branch, we're evaluating 3.1 for our next big release.

I've tried to capture as much info as I can think of below, in the hope that somebody can nail this. From our point of view, this is by far and away THE showstopper in 3.1 as it locks up our dynos in "production" if we have a method missing anywhere in our code (we _think_, I should emphasise that there's almost no way to prove that).

Here's our Gemfile.lock from the breaking branch:

https://gist.github.com/1120512

.. an example stack trace dump when pressing ctrl-C

https://gist.github.com/1120516

.. and finally, something a little more interesting, this is the FULL trace from a request which totally hangs my Rails (requiring the triple ctrl-C action) when I've been running for a while, but when starting rails s up fresh and hitting the same action with the exact same code it actually does finally time out after around 40seconds, with this trace:

https://gist.github.com/1120522

Help! :-)

matpowel picture matpowel on 2 Aug 2011

Can anyone reproduce this on their local machine? If so, please send me an email, and I'll walk you through the steps to debug. You don't need to share your application with me, but I need to get in touch with someone who can reproduce locally.

tenderlove picture tenderlove on 2 Aug 2011

I was getting it all the time (not 100%, but lots) when I started porting from 2.x to 3.1 but I backed down to 3.0 in the hope of avoiding it. I've seen it on 3.0 but less and less ... as I improve my port, and I get less errors in the code ... to now, not in a while. That said, I am pretty nervous about this bug (for me going to production w/ what I have) so I'd be game to try to reproduce it if nobody else can offer a local app. Ping me if nobody else volunteers.

adamjack picture adamjack on 2 Aug 2011

Can any of you who can still reproduce this report your Rails version and sprockets gem version please?

tanelsuurhans picture tanelsuurhans on 2 Aug 2011

People who are seeing this problem: if you upgrade to Rails 3.1.0.rc5 and sprockets beta.12, does the problem still happen?

tenderlove picture tenderlove on 2 Aug 2011

We've been able to narrow this issue down to a problem with sprockets storing concatenated assets in memory, and attaching them to an exception. Does this seem familiar @josh?

I'm looking through sprockets code, but I'm not sure what is going on.

tenderlove picture tenderlove on 2 Aug 2011

If I am adding noise but not signal I'll try to keep quiet 'cos I am new to 3.anything so not sure of what I saw nor what I am talking about... but I moved back from 3.1 to 3.0 and I believed I still hit this problem (just far less frequently.) Isn't sprockets 3.1 only not 3.0? BTW: Before downgrading I thought I'd improved things by disabling concatenating assets (I'm sorry I forget how) but it didn't make it go away.

I'd read earlier that folks thought it was to do with NameError, and I was getting a lot of those as I was porting 2.x code to 3.x. Is that thread of investigation no longer being considered?

adamjack picture adamjack on 2 Aug 2011

@tenderlove sprockets catches asset exceptions and converts them to console.log or css error messages.

https://github.com/sstephenson/sprockets/blob/master/lib/sprockets/server.rb#L66-81

That should only affect errors raised under /assets though, not the entire rails stack.

josh picture josh on 3 Aug 2011

@josh: the issue is that in sprockets beta.10 the asset cache is an instance variable on the Sprockets::Environment object. Now when a template error is raised, Sprockets catches it (https://github.com/sstephenson/sprockets/blob/v2.0.0.beta.10/lib/sprockets/context.rb#L107) and re-raises it. The exception message contains a dump (.inspect) of all the env ivars, which means it tries to dump all of the asset cache also. For some reason this seems to cause massive memory consumption and also explains why this is not reproducible with rc5 and sprockets beta.12 (the caching mechanism has changed in sprockets).
It would be nice to have this verified by people having the issue before on rc4 and upgrading to rc5.

tanelsuurhans picture tanelsuurhans on 3 Aug 2011

@tanelsuurhans ah, interesting. Can you open a sprockets issue for that. It seems like a bug to cache a template that raises an error.

josh picture josh on 3 Aug 2011

@josh was this true in beta 10? I'm looking at objects under gdb, and it seems that sprockets caches the entire file in an @cache hash.

Something is calling inspect on a Sprockets::Environment object and concatenating a string (I _think_ it's from an exception):

str buf cat

If we go to frame 3 and check out the string, it's the full source for every JS file (and some are duplicated):

frame 3

Does this seem familiar? I can't seem to find the code that would cause it, but duping and concating strings this long is probably not a good thing.

tenderlove picture tenderlove on 3 Aug 2011

What I could find out is that every file is present in @cache at least twice - once with the full path, once with just the file name.
If i remember correctly then .inspect loops over all of the objects ivars and calls .inspect on those respectively. As the NameError message seems to contain an inspection output (ActionView::Template::Error (undefined local variable or method `foo' for #<#Class:0x007fca1f165fd0:0x007fca1f161278>): - notice that the inspected object also seems to be nested), this would mean that Sprockets::Environment is one of the targets of those inspect calls.

By overriding Sprockets::Environment#inspect and logging the caller, I get this: http://pastie.org/2311514

tanelsuurhans picture tanelsuurhans on 3 Aug 2011

I could probably pretty up the sprockets inspects too.

josh picture josh on 3 Aug 2011

@tenderlove - I'll try downgrading and see if it starts happening again.

iHiD picture iHiD on 3 Aug 2011

@tenderlove, @tanelsuurhans - I've just tried downgrading to rails rc4 and spockets beta10 and the problem started happening again.

I've now gone a week with no issues on the 3.1 stable branch of rails and whichever sprockets gems that's pulling in, so I'm happy that this is resolved.

Excellent find, guys. Very unexpected place to find it. Thank for your hard work in tracking it down.

iHiD picture iHiD on 3 Aug 2011

@josh just mixin in ActiveSupport::ShortInspect from my patch above, unless there are good reasons why inspect has to be more helpful for Sprockets::Environment.

xaviershay picture xaviershay on 3 Aug 2011

Please test again on sprockets/master

sprockets 94a8fb0

josh picture josh on 3 Aug 2011

I'm so sorry to crash the part in here but all of my comments (including the pasties above, which show sprockets b.12 and rc5 in the Gemfile.lock) apply to rc5 and b.12 :-(

I spent a fair bit of time with @tenderlove trying to dtrace what's going on. It didn't seem like a big mem alloc problem right Aaron? Didn't we determine it's in a big loop trying to access files but failing or something?

@josh I'll try sprockets master now

matpowel picture matpowel on 3 Aug 2011

Furthermore, @josh and @tenderlove the problem still exists (although it does seem like it could be a lot less of a problem, ie frozen for a shorter period like 30 secs instead of 5 minutes) when using edge rails and sprockets.

Note that sprockets actually doesn't work at all for CSS and images on edge for us, so I temporarily commented out our CSS loading to be able to load our pages at all. So there is a lot less going on memory-wise which may be the real reason for the shorter freezes. Normally if I load the server, click around our site a fair bit and then hit the page with the method-missing I get a nice juicy 10min+ freeze with max CPU etc.

matpowel picture matpowel on 3 Aug 2011

@matpowel: Could you please try your app with ruby 1.9.2-p290 and see what happens then? I notice that you are using REE 1.8.7 judging by the traces you provided earlier.

tanelsuurhans picture tanelsuurhans on 3 Aug 2011

@josh: While the issue itself is already fixed in beta.12, this last commit seemingly makes the error pages appear more quickly though. Either way I am not able to reproduce the error on rails 3.rc5 and sprockets beta.12.

@matpowel: Does your app have config.assets.enabled = true (and if yes, does this issue happen if you turn it off).

tanelsuurhans picture tanelsuurhans on 3 Aug 2011

@tanelsuurhans getting up and running on 1.9.2 now (a few gems are complaining), we migrated our code to 1.9.2 initially but performance was horrific with 3.1.rc1 so we rolled back to ree.. will try it again now anyway and report.

Also yes, we have config.assets.enabled = true as because of a number of bugs in sprockets we can't rake compile our assets and need them to be served live even in production. Turning it off doesn't help anyway, ironically the method missing becomes "asset_path" :-) Only 26 seconds for the timeout but that matches the behaviour I mention above with a fresh server instance which has been "clicked around".

Rendered farm_reporting/index.html.erb within layouts/company (24855.9ms)
Completed 500 Internal Server Error in 26236ms

ActionView::Template::Error (undefined method asset_path' for #<#<Class:0x111a8b198>:0x1162b5338>): 60: <%= f.radio_button( :user_report_id, -3 ) %> Actuals PDF<br /> 61: <%= f.radio_button( :user_report_id, -4 ) %> Recommendations PDF<br /> 62: <br /> 63: <%= link_to( image_tag( asset_path( "icons/add.png" ), :alt => "" )+" Build Custom Reports", user_reports_path ) %> 64: </div> 65: <div class="left widget" style="margin-left: 20px;"> 66: <div class="title">Select Paddocks</div> app/views/farm_reporting/index.html.erb:63:in_app_views_farm_reporting_index_html_erb__229202839_2295415560'
app/views/farm_reporting/index.html.erb:50:in _app_views_farm_reporting_index_html_erb__229202839_2295415560' app/controllers/application_controller.rb:334:inset_current_user_on_model'

matpowel picture matpowel on 3 Aug 2011

@tanelsuurhans no joy, the problem still exists in 1.9.2

matpowel picture matpowel on 3 Aug 2011

@matpowel - since your request is successfully completing perhaps you could try get a rack-profiler log of it?

https://github.com/rapportive-oss/rack-perftools_profiler

tarmolehtpuu picture tarmolehtpuu on 3 Aug 2011

@tarmolehtpuu one of our guys Jason will look at it this evening (Perth time, morning in the USA) and let you know!

matpowel picture matpowel on 3 Aug 2011

@tarmolehtpuu i just gave it a quick try before heading off to bed, unfortunately the exception bails out before the perftools dump the info, any idea how to get rack-perftools to still print the info?

matpowel picture matpowel on 3 Aug 2011

I can replicate the issue me and @matpowel are having in our app by replacing ActionView::TemplateRenderer::render() with this:

    def render(context, options)
      @view = context
      crikey
    rescue NameError => e
      puts "START"
      m = e.message.to_str
      puts "STOP"
    end

There is a _massive_ pause between START and STOP, even on the first request to a fresh app. It doesn't actually matter where the exception is thrown; the pause occurs whenever message is read.

It seems something is monkey-patching NameError::message?

@tenderlove suspected Sprockets, so I added the following to Sprockets::Environment:

    def inspect
        puts "Sprockets::Environment::inspect(): #{caller[0]}"
        super
    end

That immediately revealed that e.message.to_str is calling Sprockets::Environment::inspect() somehow.

I also changed Rack::Mount::Route::inspect() as follows, although in my sleep-addled state I can't remember why:

    def inspect #:nodoc:
      puts "Rack::Mount::Route::inspect(): #{caller[0]}"
      "#<#{self.class.name} @app=#{@app.inspect} @conditions=#{@conditions.inspect} @defaults=#{@defaults.inspect} @name=#{@name.inspect}>"
    end

That causes the following to be printed:

Sprockets::Environment::inspect(): /Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:11:in `to_str'
Rack::Mount::Route::inspect(): /Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:11:in `to_str'
Rack::Mount::Route::inspect(): /Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:11:in `to_str'

...

Rack::Mount::Route::inspect(): /Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:11:in `to_str'
Rack::Mount::Route::inspect(): /Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:11:in `to_str'
STOP
Completed 200 OK in 34760ms (Views: 31376.7ms | ActiveRecord: 254.4ms)

In all, the single e.message.to_str line gives rise to 2360 calls to Sprockets::Environment::inspect() and 43772 calls to Rack::Mount::Route::inspect() and who knows what else.

Anyway, I'm due for sleep and don't have any insights. In the morning @matpowel and I will look at perftools, unless any of you have other ideas of where we should be looking in the interim. Much thanks :)

kranzky picture kranzky on 3 Aug 2011

There are seemingly two separate issues here:
a) the problem of the error message containing all the cached assets
b) the issue of .inspect being called on the objects multiple times

Sprockets::Environment#inspect is called because the NameError message is constructed by using the error description and the object it happened on, with it's inspect method being invoked to get a human readable representation of it. Inspect works by looping through all of the objects ivars and calling inspect on those also. Now considering that the template rendering is partially done in Sprockets (if the asset pipeline is enabled), it should be pretty obvious why Sprockets::Environment#inspect gets called - although it does not appear it the output. Maybe it's scrubbed later on in Rails (I recall seeing a backtrace cleaner somewhere).

tanelsuurhans picture tanelsuurhans on 3 Aug 2011

We've fixed this issue in our app by adding the following to the top of config/application.rb:

# Monkeypatch to stop the app freezing on NameError and NoMethodError
module AbstractController
  module Rendering
    module Antifreeze
      def inspect
        @view_renderer.lookup_context.find_all(@_request[:action], @_request[:controller]).inspect
      end
    end
    def view_context
      context = view_context_class.new(view_renderer, view_assigns, self)
      context.extend Antifreeze 
      return context
    end
  end
end
kranzky picture kranzky on 4 Aug 2011

@jasonhutchens: So what you are doing is cutting even more inspected data out of the error message (see sprockets related stuff a couple of posts above). I would like to ask you to first try to find out what's inside the original message thats freezing up the application, otherwise me or anyone else is unable to figure out why this issue is happening and how to really fix it.

In actionpack/lib/action_view/template/error.rb

def initialize(template, assigns, original_exception)
  super(original_exception.message)
  puts original_exception.message
  puts caller.inspect
  @template, @assigns, @original_exception = template, assigns.dup, original_exception
  @sub_templates = nil
  @backtrace = original_exception.backtrace
end

This should give you the original message and the call stack for the invocation.

tanelsuurhans picture tanelsuurhans on 4 Aug 2011

@tanelsuurhans sorry but we have a very large and stressful deadline for the end of this week. We will put some more time into it mid next week or later.

We are committed to putting back in as what we are doing is evaluating the use of 3.1 for our live site soon. I have a number of in depth blog/info type things to write up on pitfalls/experiences on 3.1, sprockets et al and I'm sure @jasonhutchens will be keen to help you resolve this issue.

In general, I wonder whether the problem is linked to a much larger problem which we haven't tackled yet which is truly shocking performance on 1.9.2. Our site is now very quick on REE 1.8.7 and unusable on 1.9.2. The problem with the inspect seems to be around large amounts of data (we're taking gigabytes it seems) being generated by #inspect calls, it makes one wonder!

matpowel picture matpowel on 4 Aug 2011

@tanelsuurhans: I thought you'd explained it pretty well. ActionView::TemplateRenderer::render throws a NoMethodError or a NameError. This results in a call to @view.inspect, which calls inspect recursively on all @view.instance_method's. So my fix just truncates @view.inspect.

Anyway, I caused an exception by adding this in our dashboard.html.erb template:

<% crikey %>

I then made the changes you described above and ran the app, requesting the dashboard, WITHOUT my monkey patch, to get this (after 36405.1ms):

undefined local variable or method `crikey' for #<#<Class:0x10557bb28>:0x1055746c0>
["/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:302:in `new'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:302:in `handle_render_error'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:147:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:40:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:33:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:33:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:39:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:47:in `render_with_layout'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:38:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:12:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:22:in `wrap_formats'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:9:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/renderer.rb:36:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/renderer.rb:17:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:120:in `_render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/streaming.rb:250:in `_render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:114:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/renderers.rb:30:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/compatibility.rb:43:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:99:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rendering.rb:16:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/benchmark.rb:308:in `realtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:78:in `cleanup_view_runtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/railties/controller_runtime.rb:24:in `cleanup_view_runtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:39:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/wicked_pdf-954af3d4a609/lib/pdf_helper.rb:16:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/implicit_render.rb:10:in `default_render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/implicit_render.rb:5:in `send_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/base.rb:167:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rendering.rb:10:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/callbacks.rb:18:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:471:in `_run__434435962__process_action__757340806__callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:207:in `_conditional_callback_around_117'", "/Users/jason/dev/website/app/controllers/application_controller.rb:359:in `set_current_user_on_model'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:206:in `_conditional_callback_around_117'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:443:in `_run__434435962__process_action__757340806__callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:386:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:386:in `_run_process_action_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/callbacks.rb:17:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rescue.rb:17:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:30:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:29:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/params_wrapper.rb:202:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/railties/controller_runtime.rb:18:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/base.rb:121:in `process'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:45:in `process'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal.rb:193:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal.rb:236:in `action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:65:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:65:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:29:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/route_set.rb:152:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:93:in `recognize'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:103:in `optimized_each'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:92:in `recognize'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/route_set.rb:141:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:531:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/bullet-2.0.1/lib/bullet/rack.rb:8:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/etag.rb:23:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/conditionalget.rb:25:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/head.rb:14:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/params_parser.rb:21:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/flash.rb:243:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:195:in `context'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:190:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/cookies.rb:326:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/query_cache.rb:62:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:466:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/callbacks.rb:29:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:392:in `_run_call_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/callbacks.rb:28:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/reloader.rb:68:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/remote_ip.rb:48:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/logger.rb:13:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/methodoverride.rb:24:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/runtime.rb:17:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/lock.rb:15:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/static.rb:53:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/engine.rb:455:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/content_length.rb:16:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/log_tailer.rb:14:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/handler/webrick.rb:59:in `service'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/httpserver.rb:104:in `service'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/httpserver.rb:65:in `run'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:173:in `start_thread'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:162:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:162:in `start_thread'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:95:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:92:in `each'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:92:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:23:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:82:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/handler/webrick.rb:13:in `run'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/server.rb:265:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands/server.rb:70:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:54", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:49:in `tap'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:49", "script/rails:6:in `require'", "script/rails:6"]

I then re-ran the test, but this time WITH my monkey patch, to get this (after 23.5ms):

undefined local variable or method `crikey' for app/views/users/dashboard.html.erb():#<Class:0x1054b6350>
["/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:302:in `new'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:302:in `handle_render_error'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/template.rb:147:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:40:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:33:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:33:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:39:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:47:in `render_with_layout'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:38:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:12:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/abstract_renderer.rb:22:in `wrap_formats'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/template_renderer.rb:9:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/renderer.rb:36:in `render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_view/renderer/renderer.rb:17:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:120:in `_render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/streaming.rb:250:in `_render_template'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:114:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/renderers.rb:30:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/compatibility.rb:43:in `render_to_body'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:99:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rendering.rb:16:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/benchmark.rb:308:in `realtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:78:in `cleanup_view_runtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/railties/controller_runtime.rb:24:in `cleanup_view_runtime'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:39:in `render_without_wicked_pdf'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/wicked_pdf-954af3d4a609/lib/pdf_helper.rb:16:in `render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/implicit_render.rb:10:in `default_render'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/implicit_render.rb:5:in `send_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/base.rb:167:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rendering.rb:10:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/callbacks.rb:18:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:471:in `_run__434435962__process_action__757340806__callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:207:in `_conditional_callback_around_117'", "/Users/jason/dev/website/app/controllers/application_controller.rb:359:in `set_current_user_on_model'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:206:in `_conditional_callback_around_117'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:443:in `_run__434435962__process_action__757340806__callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:386:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:386:in `_run_process_action_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/callbacks.rb:17:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rescue.rb:17:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:30:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/notifications.rb:55:in `instrument'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/instrumentation.rb:29:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/params_wrapper.rb:202:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/railties/controller_runtime.rb:18:in `process_action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/base.rb:121:in `process'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/abstract_controller/rendering.rb:45:in `process'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal.rb:193:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_controller/metal.rb:236:in `action'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:65:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:65:in `dispatch'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:29:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/route_set.rb:152:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:93:in `recognize'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:103:in `optimized_each'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/code_generation.rb:92:in `recognize'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-mount-0.8.1/lib/rack/mount/route_set.rb:141:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/routing/route_set.rb:531:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/bullet-2.0.1/lib/bullet/rack.rb:8:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/etag.rb:23:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/conditionalget.rb:25:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/head.rb:14:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/params_parser.rb:21:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/flash.rb:243:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:195:in `context'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:190:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/cookies.rb:326:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/query_cache.rb:62:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:466:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/callbacks.rb:29:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:392:in `_run_call_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `send'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/callbacks.rb:28:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/reloader.rb:68:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/remote_ip.rb:48:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/logger.rb:13:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/methodoverride.rb:24:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/runtime.rb:17:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/lock.rb:15:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/actionpack/lib/action_dispatch/middleware/static.rb:53:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/engine.rb:455:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/content_length.rb:16:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/rack/log_tailer.rb:14:in `call'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/handler/webrick.rb:59:in `service'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/httpserver.rb:104:in `service'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/httpserver.rb:65:in `run'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:173:in `start_thread'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:162:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:162:in `start_thread'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:95:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:92:in `each'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:92:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:23:in `start'", "/Users/jason/.rvm/rubies/ree-1.8.7-2011.03/lib/ruby/1.8/webrick/server.rb:82:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/handler/webrick.rb:13:in `run'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/gems/rack-1.3.2/lib/rack/server.rb:265:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands/server.rb:70:in `start'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:54", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:49:in `tap'", "/Users/jason/.rvm/gems/ree-1.8.7-2011.03/bundler/gems/rails-7ee15e8a0f84/railties/lib/rails/commands.rb:49", "script/rails:6:in `require'", "script/rails:6"]

TLDR; no difference, apart from the _slightly_ more useful error message.

kranzky picture kranzky on 4 Aug 2011

The only difference that I can spot is #<#Class:0x10557bb28:0x1055746c0> vs #Class:0x1054b6350 in the message.
The latter one would suggest that nested object inspects were skipped, thus giving a flat object inspect instead of a nested one and resulting in faster error throwing.

Still not sure if this issue is caused by too much data in the object trees ivars, or by the fact that those .inspect calls end up in a loop somehow. Or both. The first issue would need to be eliminated via having .inspect overrides with minimal data (as the default behavior of inspecting all the objects ivars comes from ruby, and I don't think we are going to change that). But the second issue still needs some clarification first.

@jasonhutchens: Can I ask you one more thing please? Could you post your Gemfile.lock

tanelsuurhans picture tanelsuurhans on 4 Aug 2011

Hi @tanelsuurhans,

I posted our Gemfile.lock above, @jasonhutchens is using the same:

https://gist.github.com/1120512

Thanks for looking into this.

matpowel picture matpowel on 4 Aug 2011

@tanelsuurhans: We can answer some of your questions by extending my patch to print out some debugging information, like this:

    module Antifreeze
      @@indent = 0
      def inspect
        puts "   " * @@indent + "BEG INSPECT ##{object_id}"
        @@indent += 1
        instance_variables.each do |i|
            v = instance_variable_get "#{i}".to_sym
            start = Time.now
            puts "   " * @@indent + "#{i} #{v.class.name} ##{v.object_id}"
            v.inspect
            puts "   " * @@indent + "(#{1000 * (Time.now - start)}ms)"
        end 
        @@indent -= 1
        puts "   " * @@indent + "END INSPECT ##{object_id}"
        return ""
      end
    end

You'll notice I'm looping through the instance variables and calling inspect on them, in an attempt to emulate the default implementation of inspect. Here are the edited results (for clarity, I've removed instance variables which don't recurse and are quick to inspect):

BEG INSPECT #2191884540
   @_request ActionDispatch::Request #2201021240
   BEG INSPECT #2191884540
      ...
   END INSPECT #2191884540
   (4528.217ms)
   @view_renderer ActionView::Renderer #2191908220
   BEG INSPECT #2191884540
      @_request ActionDispatch::Request #2201021240
      (4137.892ms)
      @_controller UsersController #2201021360
      (12622.849ms)
   END INSPECT #2191884540
   (16761.496ms)
   @_controller UsersController #2201021360
   BEG INSPECT #2191884540
      @_request ActionDispatch::Request #2201021240
      (3869.411ms)
   END INSPECT #2191884540
   (16323.756ms)
END INSPECT #2191884540

So there's definitely recursion; four inspect calls to the same object instead of one. It seems @_request, @_controller and @view_renderer are of interest. This "monkey debugging" can be continued in the obvious way to delve into those in an attempt to find the source of the recursion. The details are too long for this comment form to contain, but it boils down to this:

  • The exception is called, we inspect the template renderer, and this causes @_request to be inspected
  • The _@request (an ActionDispatch::Request) contains an @env hash, which is inspected

    • This contains @env[action_dispatch.remote_ip] (an ActionDispatch::RemoteIp::RemoteIpGetter)

    • Inspecting this (eventually) calls inspect on UserController (would be nice to know where this happens)

    • It also calls inspect on the same request object three additional times, it seems

    • This has a @_view_renderer, which, when inspected, causes the ActionView::Renderer to be inspected

    • This causes our template renderer to be inspected again, which, in turn, causes the same ActionDispatch::Request to be inspected...

So you can see that the call chain is _template_ -> _request_ -> _controller_ -> _renderer_ -> _template_. This causes the first recursion you see. Next, the template renderer contains @_view_renderer, which results in _template_ -> _renderer_ -> _template_, and it also contains @_controller, resulting in _template_ -> _controller_ -> _renderer_ -> _template_.

Presumably along the line lots of Sprockets::Environment::inspect() and Rack::Mount::Route::inspect() calls are made, and are probably responsible for a lot of the slowdown (you can see from above that the first recursion takes 4.5 seconds, while the second and third take over 16 seconds?

That's as far as I've got at the moment. I hope it joins the dots for someone? And I'm not sure whether I'm barking down the wrong path or not; this is the first time I've looked at the Rails source in any detail, and I don't know my Ruby internals (i.e. how inspect works) too well.

Right now I'm wondering whether the recursion has got anything to do with how the view context is created (i.e. an anonymous class returned by ActionView::Base.prepare()). Perhaps something's going on to prevent the default implementation of inspect from detecting recursion, which it surely must be trying to do?

kranzky picture kranzky on 4 Aug 2011

I've fixed this on 3-1-stable by reverting 403b06e right here: cdf6251

I'm keeping this ticket open, but moving it to 3.2. I think this is a symptom of a problem, and the problem is that we're holding references to too much stuff. I'd like to get the references down in 3.2 so that calling inspect is not so painful.

tenderlove picture tenderlove on 10 Aug 2011

@tenderlove: fwiw, that patch does _not_ fix the issue for us

I've modified the monkeypatch we use to be more inclusive, as we were still getting a freeze on a NameError within a controller. This is now the patch we're using:

module ActionDispatch
  module Routing
    class RouteSet
      alias inspect to_s
    end
  end
end

We can instrument this for debugging as follows:

module ActionDispatch
  module Routing
    class RouteSet
      alias old_inspect inspect
      def inspect
        start = Time.now
        retval = old_inspect
        elapsed = Time.now - start
        puts "#{elapsed}|#{retval.length}" if elapsed > 1.0
        retval
      end
    end
  end
end

That produces the following output for our case of a NameError in a template:

5.199491|5890102
4.981274|5892448
5.256369|5892448
4.499855|5892448
4.390188|5892448
4.402916|5892448
4.881419|5892448

As for the contents of retval (a 5+MB string that is generated 7 times), please see http://pastie.org/2356074. I haven't pasted the entire thing; I've gone through and redacted bits (which are marked with ...nnn..., where nnn is the number of characters removed), and indented to make the nesting more obvious. There's definitely no js source in it, however.

kranzky picture kranzky on 11 Aug 2011

These seem to be two closely related but slightly different issues. The first one, which was caused by calling exception#message, crashed the whole app process due to a seemingly endless loop inside the #inspect implementation of ruby. The bug you are having seems to be caused by a huge env dump. I'm guessing your app is relatively big?

tanelsuurhans picture tanelsuurhans on 11 Aug 2011

I think @tanelsuurhans is probably correct. It looks like you have many routes. My patch should prevent that string from getting duped (which just goes back to Rails 3.0 behavior). In other words, I suspect that this problem would also occur on Rails 3.0.

The real solution is to reduce the number of objects to which we're holding references. After my revert, we should be no worse than Rails 3.0 behavior, but IMO this bug is by no means "fixed" (which is why I left it open).

tenderlove picture tenderlove on 11 Aug 2011

In that case, I'm not sure we ever got the endless loop bug. We just get extremely long pauses on NameError and NoMethodError (and your patch didn't speed things up, but, sure, the app probably used less memory).

It's fine to reduce the number of references held, but why not have a policy like "always implement inspect if you implement to_s" and "always implement inspect if you contain a large number of complex ivars" or something like that? Reducing the size of RouteSet.inspect from 5MB to, say, 5k by reducing held references is still of dubious utility (is anyone really going to find 5k strings in stack traces useful when debugging)?

kranzky picture kranzky on 12 Aug 2011

I agree. But the point of my patch is to relieve pressure from the 3.1 release. We're reverting to 3.0 behavior in order to buy more time.

tenderlove picture tenderlove on 12 Aug 2011

I've been having this bug in my own app - FWIW, I'm using jasonhutchens' alias inspect to_s patch, and it's working around the problem nicely for the issues I was hitting.

I thought it might be a useful data point to point out that with that patch in place, <%= undefined_variable %> returns the "name error" / undefined local variable error we expect. But if I say <% raise undefined_variable %> that kicks off the infinite memory-eating loop.

Not sure if that has any bearing on the research, but I figured I'd rather say something redundant than sit on something important. Cheers!

marktabler picture marktabler on 12 Aug 2011

@marktabler: I've just tried your <% raise undefined_variable %> and don't get the infinite loop. You might be hitting the Sprockets bug mentioned earlier in this thread?

kranzky picture kranzky on 12 Aug 2011

Ah, looks like I am. I'll see about upgrading to RC5 over the weekend and report on what my status is.

marktabler picture marktabler on 12 Aug 2011

This has been driving me nuts and causing issues with my production app. At least I think it's the same issue. Something makes the process hang when there's an error.

inspire22 picture inspire22 on 8 Nov 2011

@inspire22

For me the fix is to remove "table_exists?" check from def inspect on AR base.rb. Memoizing the result is probably better than this hack, but it'll do for me...

Rack::Mount is calling "inspect" seriously large numbers of times (* 4ms per call to table_exists with my mysql setup) when you have a non trivial routes file (instant with 1 route, but for a real app it takes upwards of 7 seconds) and something 500s.

Reproducible for me with unicorn and mongrel, it's not just webrick.

lypanov picture lypanov on 8 Nov 2011

We are experiencing the same problem porting our rails 2.3.14 app to Rails 3.1 (Rails freezes with high memory leak when a NameError or NoMethodError exception happens in a view). @matpowel : I think our app falls into the the "large, commercial, production apps" category too... It's quite annoying since we can't deploy our Rails 3.1 in production with this unexplained and heavy bug.

Among the patches proposed above, which one is the winner ? Could you please explain me how to apply it ? Thanks a lot.

Details : Ruby 1.8.7, Rails 3.1 on Webrick with asset pipeline enabled (local app on my MacBook Pro)

flackou picture flackou on 10 Nov 2011

try without asset pipeline (I.E with jammit), we are currently deploying our 3.1 apps that way and it helps

tarmolehtpuu picture tarmolehtpuu on 10 Nov 2011

Try this patch:

module ActionDispatch
  module Routing
    class RouteSet
      alias inspect to_s
    end
  end
end

It's probably easiest to create a new file called anti_freeze.rb that contains this patch and put it in config/initializers.

kranzky picture kranzky on 10 Nov 2011

Thanks a lot, in my case the antifreeze patch seems to solve the problem. Hope we will find a "proper" way to fix this in Rails core.

flackou picture flackou on 11 Nov 2011

@jasonhutchens you made my week with that monkey patch! My production server went live on RoR 3.1 and then dead within no time, then down for days despite all my efforts. Applying this patch brought it back to life, and allowed me to track down the NameError that was sucking the life out of it. THANK YOU! :)

adamjack picture adamjack on 11 Nov 2011

Today I've discovered (running rails 3.1.1) that when I put call to non-existing method to the view (erb, haml, doesn't matter) my local mysql server just can't get enough of CPU power.

For example, this is from the log when this happened:

Rendered shared/_menu.html.erb (0.2ms)
Rendered account/_menu.html.haml (8.4ms)
Rendered payments/new.html.erb within layouts/dashboard (120250.9ms)
Completed 500 Internal Server Error in 120566ms

Then the error came out in the browser:

NoMethodError in Payments#create
Showing /Users/.../Sites/.../app/views/payments/new.html.erb where line #10 raised:
undefined method `error_fields' for #<ActionView::Helpers::FormBuilder:0x007fd9aeb94440>

10:   <%= f.error_fields %>

How can those two things be related? How can throwing an error cause mysql server to eat cpu like dirty devil?
(and yes, I'm pretty sure mysqld cpu usage ramped up only because of this, it happened twice this very day and stopped when the error message was thrown on the screen).

It looked like rails tried to connect and connect and connect to mysql

Rails 3.1.1
Mysql2 gem 0.3.6
Ruby 1.9.3-p0
OS X 10.7.2 Lion (11.2.0 Darwin Kernel Version 11.2.0)
MySQL server 5.5.9

EDIT:

@lypanov I've read your comment too late... If it's calling to table_exists? every time that would be the cause of my discovery.
@jasonhutchens Your patch works like a charm, thanks!

daliborfilus picture daliborfilus on 2 Dec 2011

Great stuff - the "proper" fix in Rails I suppose is either to implement meaningful versions of inspect instead of relying on default behaviour, and/or to avoid calling inspect altogether. And, of course, minimising held references to reduce the number and complexity of instance variables in the first place.

The default implementation of inspect recursively calls inspect on all instance variables. Calling inspect on top-level Rails objects, like the view itself, can chew up resources.

kranzky picture kranzky on 2 Dec 2011

@tenderlove should we move this out of the 3.2 milestone?

jonleighton picture jonleighton on 20 Dec 2011

Thank you @jasonhutchens, that patch did the trick for me too. This issue would sometimes render my Linux computer unusable for long enough to make me force a restart - not fun. Recently I've been running with the line 'debugger' in the Route#inspect method just to catch it and restart my server before it eats all my resources.

jamesds picture jamesds on 21 Dec 2011

@jamesds Why not just kill the process? There is something very wrong if a user space non superuser process is able to render a machine unusable.

betelgeuse picture betelgeuse on 21 Dec 2011

@betelgeuse I ran with the hack after it happened badly for the first time. I was exaggerated slightly, though. I could kill the server process but the computer was still very sluggish for a while, even after restarting the DB. Not sure if it was swapping like crazy, but a few times it was just quicker to restart than work out why it was slow or work out how to fix it.

jamesds picture jamesds on 21 Dec 2011

@jasonhutchens Thanks a lot. I've been dealing with this issue for a few months in development with Rails 3.0.3 and 3.0.11, but it didn't rise to a level of importance until it hit our production server this week :) and I finally found this thread.

Your patch solved it for me in Rails 3.1.3. Before I just had to kill and restart the development server. That was faster than waiting for the error to finally bubble up. Thanks!

Edit: @jasonhutchens' patch actually only worked in Rails 3.1.3. For Rails 3.0.11, we used @AndreyChernyh's patch, which raises the errors faster, but still impendingly slow.

hundredwatt picture hundredwatt on 12 Jan 2012

@jasonhutchens - Thank you a lot! I had the same problem with ruby 1.9.3 and rails 3.1.3 - your patch solved it!

santuxus picture santuxus on 22 Jan 2012

I think I'm also getting this problem on a few of my Rails 3.1 and 3.2 apps.

joevandyk picture joevandyk on 31 Jan 2012

@joevandyk Try the patch from @jasonhutchens in the comments above (November 10th 2011) and hopefully you'll be smiling/thanking him, like a number of us. :)

adamjack picture adamjack on 31 Jan 2012

I did, and it worked great! I've been annoyed by this bug for months,
it was hard to find this GH issue about it. I'm not using webrick, so
the title was misleading.

On Jan 31, 2012, at 9:56 AM, Adam Jack
[email protected]
wrote:

@joevandyk Try the patch from @jasonhutchens in the comments above (November 10th 2011) and hopefully you'll be smiling/thanking him, like a number of us. :)

Reply to this email directly or view it on GitHub:
https://github.com/rails/rails/issues/1525#issuecomment-3744128

joevandyk picture joevandyk on 31 Jan 2012

I hear that! I bet a bunch of folks are suffering this, and it killed me for a long time before the monkey patch came out. Any thoughts on how to spread the word, since a fix for it doesn't appear forthcoming.

Btw: you ought now be seeing exceptions in your code (that you can fix) now the logs are coming out. The root source of the problem. :-)

Adam

Sent from my iPad

On Jan 31, 2012, at 6:27 PM, Joe Van [email protected] wrote:

I did, and it worked great! I've been annoyed by this bug for months,
it was hard to find this GH issue about it. I'm not using webrick, so
the title was misleading.

On Jan 31, 2012, at 9:56 AM, Adam Jack
[email protected]
wrote:

@joevandyk Try the patch from @jasonhutchens in the comments above (November 10th 2011) and hopefully you'll be smiling/thanking him, like a number of us. :)

Reply to this email directly or view it on GitHub:
https://github.com/rails/rails/issues/1525#issuecomment-3744128

Reply to this email directly or view it on GitHub:
https://github.com/rails/rails/issues/1525#issuecomment-3744788

adamjack picture adamjack on 31 Jan 2012

@tenderlove would you be willing to change the title / description of this issue to make it more easily discoverable for those who are hitting this problem (based on the comment by @joevandyk above)? Something like "Exception in View Freezes Rails"?

Also, is it possible to divorce this symptom from the underlying cause? It seems to me that the fact that several people are struggling with this for months in development, and that it's affecting production apps, makes a fix a higher priority than 4.0? Reducing the number of held references, on the other hand, is an optimisation that arguably could wait that long.

And @adamjack; the fix really is just to implement sane inspect methods for RouteSet and so on. The entire problem is that we're hitting the default implementation of inspect on top-level, long-lived rails objects that hold references to everything. The default implementation builds a massive string which is time consuming, memory intensive and of no practical use.

kranzky picture kranzky on 1 Feb 2012

@jasonhutchens : I updated the title as upon your request.

ndemoreau picture ndemoreau on 1 Feb 2012

@jasonhutchens Thanks for the patch, worked wonderfully for me (Ruby 1.9.3-p0, Rails 3.2.1).

freedomsoft picture freedomsoft on 11 Feb 2012

@jasonhutchens Thanks. This patch is working well for our huge app. It helps me a lot to debug thousands of missing methods exceptions following our migration from Rails 2.3 .

aq picture aq on 14 Feb 2012

Hi @aq, glad to hear the patch worked for you. One question, since you're doing the same thing we did a while ago in upgrading a very large app to Rails 3.1 (I work with @jasonhutchens), have you guys also moved to Ruby 1.9.3? We find the performance unacceptable compared to REE 1.8.7 because of very poor GC performance, so I'm checking with other people with very large apps. Thanks, Matt

matpowel picture matpowel on 14 Feb 2012

I'm (misery loves company) glad to hear somebody else say that. I worked hard to improve performance when I upgraded from 2.x to 3.1, and yet my new app is so slow (on exactly the same hardware) that I've found myself page caching almost everything (and more than I should.) The app instances bloat (when before they didn't, and I've worked hard to optimize & route out leaks/bloats.) Basically I don't know where to turn next to get back to the performance I had with 2.x.

So, long whine short, and not that this is the place for it ... but any ideas for improving performance (be it new ruby or what) would be appreciated.

adamjack picture adamjack on 14 Feb 2012

Yes @matpowel we are using 1.9.3, but I am currently debugging and I have no numbers to compare with 1.8.7 .

@adamjack for us, lazy loading of 2.5MB of config data stored in yaml files will be the first step.

aq picture aq on 14 Feb 2012

The patch from @jasonhutchens worked perfect for me (Ruby 1.8.7, Rails 3.2.1).

DriesS picture DriesS on 15 Feb 2012

@DriesS: I really have to ask - why on earth are you still using 1.8.7 with Rails 3.2.1? Afaik Rails dropped official support for 1.8.7 from 3.x onwards. I really suggest you upgrade your ruby version, you will get insane performance boots from using 1.9.3

tanelsuurhans picture tanelsuurhans on 15 Feb 2012

@tanelsuurhans rails supports 1.8.7 until 4.0

betelgeuse picture betelgeuse on 15 Feb 2012

Okay, I was on that one then. Doesn't really change the fact that 1.8.7 is dog slow compared to 1.9.3, not to mention the memory usage :)

As a side note - I've encountered this bug a couple of times on a 3.2.1 project too, although its not as bad as it was with 3.0.x, just eats a up a bit of memory and spits out the TemplateError.

tanelsuurhans picture tanelsuurhans on 15 Feb 2012

never ending issue :)

Would it make sense to write custom inspect methods for rails core classes (at least the huge ones) to make this go away?

tarmolehtpuu picture tarmolehtpuu on 15 Feb 2012

@tarmolehtpuu I think that an idiom of "implement inspect for complex classes" is good practice in general; after all, who is inspect for (developers, right)? So the default implementation, which, in our case, returns a 20MB string for the view, is pretty useless! I mean, 20MB is the complete works of shakespeare, the bible, all the sherlock holmes stories, and a bunch of other stuff. Hence my comment about separating symptom from cause above: https://github.com/rails/rails/issues/1525#issuecomment-3753956

@tanelsuurhans all evidence we have to have to hand is that 1.9.x performance is worse than ree 1.8.7 for our app; it's quite likely GC related; we've not had enough time to investigate

kranzky picture kranzky on 15 Feb 2012

Ping. Seriously. Still no fix for this in Rails 3.2.1? I'm find the RouteSet hack (added via initializer) works for me.

module ActionDispatch
  module Routing
    class RouteSet
      alias inspect to_s
    end
  end
end
joshgoebel picture joshgoebel on 16 Feb 2012

I created a sample app that shows how rails hangs when getting a view error. https://github.com/joevandyk/rails-view-errors-hanging Essentially I created an empty Rails 3.1.3 app with a couple thousand routes and put an undefined method call in the view. I also made a 3.2 branch -- that one seems to hang for much longer.

For me, it only hangs for 5-6 seconds, but I'm sure the root cause of the slowness is the same as mentioned above where Rails can hang for minutes for larger apps.

As mentioned in the README, I'm positive this problem can show itself without having a thousand+ routes, but the slowness is fixed by the above Routeset fix.

joevandyk picture joevandyk on 16 Feb 2012

I am using Rails 3.2.1 and the same is happening with me. whenever a method isn't find it takes forever to not throw the error. And memory usage going up and up and it almost use all of my system memory if i dont kill the server manually and sometimes killing the server doesnt work easily. Please we need a fix.

akashkamboj picture akashkamboj on 19 Feb 2012

Encountered this problem yesterday in production :( RouteSet hack works for me now.

barttenbrinke picture barttenbrinke on 21 Feb 2012

Out of curiosity, I've had a bit more of a look into this issue. The problem is internal to the Ruby interpreter; Rails isn't scrubbing this exception message as suspected by @tanelsuurhans seven months ago.

The root cause is name_err_mesg_to_str, which _always_ calls the inspect method of the object throwing the exception when constructing the message for a NameError or a NoMethodError. Which is pretty much what @tarmolehtpuu found in his first debugging session. This is the (1.9.2) code:

d = rb_protect(rb_inspect, obj, 0);
if (NIL_P(d) || RSTRING_LEN(d) > 65) {
  d = rb_any_to_s(obj);
}
desc = RSTRING_PTR(d);

...

if (desc && desc[0] != '#') {
  d = d ? rb_str_dup(d) : rb_str_new2(desc);
  rb_str_cat2(d, ":");
  rb_str_cat2(d, rb_obj_classname(obj));
}

args[0] = mesg;
args[1] = ptr[2];
args[2] = d;
mesg = rb_f_sprintf(NAME_ERR_MESG_COUNT, args);

That is:

  • Call inspect on the object that raised the exception
  • If the string returned is nil, or is more than 65 characters long, then call rb_any_to_s, which returns a string of the form #<CLASSNAME:ADDRESS>
  • If the string doesn't start with a #, then add the class name to the end of the string
  • Build the exception message via rb_f_sprintf

Now, when a NameError or NoMethodError is thrown from a view, any access of the message of the resulting exception object will cause name_err_mesg_to_str to be invoked, which in turn will call inspect on the object which raised the exception, very probably discarding the results.

The default implementation of inspect, as we now all know, can be resource hungry for large, complex objects. One perfectly reasonable fix, I think, would therefore be for name_err_mesg_to_str to call rb_inspect _only_ _if_ it had been overridden (that is, to never call the default implementation for an object). But that's as maybe. The fix for us is to ensure that we don't allow the default implementation of inspect to be called. Which is as simple as overriding it. Which is what the "RouteSet Hack" does.

Here's a simple test that replicates the issue in plain Ruby:

def test_slow_inspect
  require 'benchmark'
  SlowInspect.new.raise_name_error
rescue NameError => e
  time = Benchmark.realtime { puts e.message }
  puts "(done in #{(time*1000).to_i} ms)"
end

class SlowInspect
  def initialize(l=0)
    @foo = []
    10.times { @foo << ( l > 4 ? self : SlowInspect.new(l+1) ) }
  end
  def raise_name_error
    shazbut
  end
end

test_slow_inspect

class SlowInspect
  alias inspect to_s
end

test_slow_inspect

which prints the following on my machine:

undefined local variable or method `shazbut' for #<SlowInspect:0x105213990>
(done in 4593 ms)
undefined local variable or method `shazbut' for #<SlowInspect:0x10499fae8>
(done in 0 ms)

Note that the _result_ of calling e.message here is identical (well, apart from the address of the object); the only difference is that we're reducing the overhead of the call to inspect by overriding its default implementation.

In pure Ruby terms, "implement inspect for complex classes" is a good idiom. And, if you're bothering to do that, then "keep the length of the string returned by inspect no more than 65 characters" is a useful corollary, as it will yield more informative error messages for NameError and NoMethodError exceptions.

kranzky picture kranzky on 21 Feb 2012
👍3

The fix for this bug has arrived on the 3.2 and 3.1 stable branches.

joevandyk picture joevandyk on 27 Mar 2012

For those who might stumble upon dirty fixes for this issues in "old" projects, I can confirm that this issue has been fixed in 3.2.3.

The changelog doesn't cleary stipulates it (you can't look up #1525).

tgautier-silicon picture tgautier-silicon on 18 Apr 2012

I always create the changelog on the fly using github : https://github.com/rails/rails/compare/v3.2.2...v3.2.3
There it says it got included :)

barttenbrinke picture barttenbrinke on 18 Apr 2012

The changelog does say the cause for the bug (routeset inspection) was
fixed. But unfortunately it doesn't mention the actual bug (freezing,
memory growth on view errors).

On Apr 18, 2012, at 3:40 AM, Thomas Gautier
[email protected]
wrote:

For those like me who're used to check changelogs, I confirm that this issue has been fixed in 3.2.3 even if the changelog http://weblog.rubyonrails.org/2012/3/30/ann-rails-3-2-3-has-been-released/ doesn't say so.

Reply to this email directly or view it on GitHub:
https://github.com/rails/rails/issues/1525#issuecomment-5195884

joevandyk picture joevandyk on 18 Apr 2012
Was this page helpful?
0 / 5 - 0 ratings

Related issues

elado picture elado  路  63Comments
egru picture egru  路  51Comments
icanhasserver picture icanhasserver  路  52Comments
jduff picture jduff  路  78Comments
rishav picture rishav  路  66Comments