Ruby exception.message 花费太多时间

Question

我看到了 ruby​​ 的非常有趣和灾难性的行为，请看下面的代码

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

理想情况下，ex.message 不应花费任何时间来执行，因此所用时间应以毫秒为单位，但这是输出

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

如果我将 [0]*500000 分配给局部变量而不是实例变量，例如result = [0]*500000 它按预期运行

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

看起来 ex.message 不知何故在实例变量中循环，为什么会这样，请赐教!

我已经在 ruby​​ ruby​​-1.9.2-p290、ruby-1.9.1-p376、ruby 2.0.0 以及 codepad.org 上的任何版本的 ruby​​ 上试过了。

编辑:提交错误 http://bugs.ruby-lang.org/issues/8366

Answer 1

深入研究后the source ，我发现 NameError#message 尝试先在您的对象上调用 inspect，如果该字符串太长，它会调用 to_s。预计 inspect 会花费很长时间，因为它会递归地检查每个实例变量。 (查看 documentation 进行检查。)

来自错误.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);

你可以归结这个测试，看看它毕竟与异常无关:

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

如果您知道您的类将保存大量数据并可能抛出大量异常，理论上您可以覆盖 #inspect。

class InspectTest
  def inspect
    to_s
  end
end

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