Ruby exception.message taking too much time

Question

I am seeing very interesting and catastrophic behavior with ruby, see the code below

class ExceptionTest

  def test
    @result = [0]*500000

    begin
      no_such_method
    rescue Exception => ex
      puts "before #{ex.class}"
      st = Time.now
      ex.message
      puts "after #{Time.now-st} #{ex.message}"
    end

  end
end

ExceptionTest.new.test

Ideally ex.message should not take any time to execute and hence Time taken should be in ms, but here is the output

before NameError
after 0.462443 undefined local variable or method `no_such_method' for #<ExceptionTest:0x007fc74a84e4f0>

If I assign [0]*500000 to a local variable instead of instance variable e.g. result = [0]*500000 it runs as expected

before NameError
after 2.8e-05 undefined local variable or method `no_such_method' for #<ExceptionTest:0x007ff59204e518>

It looks like somehow ex.message is looping thru the instance variables, why it would do so, please enlighten me!

I have tried it on ruby ruby-1.9.2-p290, ruby-1.9.1-p376, ruby 2.0.0 and whatever version the ruby on codepad.org is.

Edit: files a bug http://bugs.ruby-lang.org/issues/8366

Answer 1

After digging into the source, I found that NameError#message tries to call inspect on your object first, and if that string is too long, it calls to_s instead. It's expected that inspect would take a long time because it recursively inspects every instance variable. (See the documentation for inspect.)

From error.c:

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

You can boil down this test to see that it has nothing to do with exceptions after all:

class InspectTest
  def initialize
    @result = [0]*500000
  end

  def test
    puts "before"
    st = Time.now
    self.inspect
    puts "after #{Time.now-st}"
  end
end

InspectTest.new.test
#before
#after 0.162566

InspectTest.new.foo
# NoMethodError: undefined method `foo' for #<InspectTest:0x007fd7e317bf20>

e=InspectTest.new.tap {|e| e.instance_variable_set(:@result, 0) }
e.foo
# NoMethodError: undefined method `foo' for #<InspectTest:0x007fd7e3184580 @result=0>
e.test
#before
#after 1.5e-05

If you know your class will hold tons of data and might throw lots of exceptions, you could in theory override #inspect.

class InspectTest
  def inspect
    to_s
  end
end

InspectTest.new.test
#before
#after 1.0e-05