【一人 bugs.ruby Advent Calendar 2021】[Misc #18285] NoMethodError#message uses a lot of CPU/is really expensive to call【12日目】

一人 bugs.ruby Advent Calendar 2021 12日目の記事になります。
今回は特定の条件下で NoMethodError#message がパフォーマンス的にコストがかかる話です。

[Misc #18285] NoMethodError#message uses a lot of CPU/is really expensive to call

NoMethodError#message がパフォーマンス的にコストがかかるというチケットです。
これは dd-trace-rb の内部テストで問題になったらしい。
参照記事：：the unexpected cost of ruby's NoMethodError exception
実際にチケットで提示されているベンチマークは以下の通り。

require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'

  gem 'benchmark-ips'
end

puts RUBY_DESCRIPTION

class GemInformation
  def get_no_method_error
    method_does_not_exist
  rescue => e
    e
  end

  def get_runtime_error
    raise 'Another Error'
  rescue => e
    e
  end

  # NoMethodError#message でこのメソッドが呼び出される
  # Rails の Controller だと複雑な #inspect が実装されておりそれがボトルネックになっているらしい
  def inspect
    Gem::Specification._all.inspect
  end
end

NO_METHOD_ERROR_INSTANCE = GemInformation.new.get_no_method_error
RUNTIME_ERROR_INSTANCE = GemInformation.new.get_runtime_error

Benchmark.ips do |x|
  x.config(:time => 5, :warmup => 2)

  x.report("no method error message cost") { NO_METHOD_ERROR_INSTANCE.message }
  x.report("runtime error message cost") { RUNTIME_ERROR_INSTANCE.message }

  x.compare!
end

__END__

output:
ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-linux]
Warming up --------------------------------------
no method error message cost
                        20.000  i/100ms
runtime error message cost
                         1.620M i/100ms
Calculating -------------------------------------
no method error message cost
                        249.716  (± 6.0%) i/s -      1.260k in   5.068273s
runtime error message cost
                         16.046M (± 1.1%) i/s -     81.020M in   5.049800s

Comparison:
runtime error message cost: 16045983.5 i/s
no method error message cost:      249.7 i/s - 64256.99x  (± 0.00) slower

このだとめっちゃ遅いですね…これは NoMethodError#message が #inspect を呼び出しているのが原因らしいです。
以下、サンプルコード

class NoInspect
end

begin
  NoInspect.new.hoge
rescue => e
  pp e.message
  # => "undefined method `hoge' for #<NoInspect:0x00005644abd35978>"
end

class WithInspect
  def inspect
    "My WithInspect"
  end
end

begin
  WithInspect.new.hoge
rescue => e
  # メッセージに WithInspect#inspect も含められる
  # error: undefined method `hoge' for My WithInspect:WithInspect (NoMethodError)
  pp e.message
  # => "undefined method `hoge' for My WithInspect:WithInspect"
end

Rails の Controller だと #inspect が複雑になっているので結果的に NoMethodError#message がボトルネックになっているとのこと。
ちなみに Ruby 3.0 以前は #inspect の文字数が66文字以上だと #message に含まれていなかったらしい。

class WithInspect
  def inspect
    "A" * 66
  end
end

begin
  WithInspect.new.hoge
rescue => e
  pp e.message
  # Ruby 2.7 => "undefined method `hoge' for #<WithInspect:0x000055a784c8a560>"
  # Ruby 3.0 => "undefined method `hoge' for AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA:WithInspect"
end

これは知らんかった。