From: "ivoanjo (Ivo Anjo) via ruby-core" <ruby-core@...>
Date: 2023-01-07T13:23:34+00:00
Subject: [ruby-core:111725] [Ruby master Feature#18285] NoMethodError#message uses a lot of CPU/is really expensive to call

Issue #18285 has been updated by ivoanjo (Ivo Anjo).





> The vast majority of classes out there don't define a custom inspect. So Ruby should do something reasonable for these cases.



+1 My intention with my bug report was to call this out -- `inspect` can get really expensive, and you just need a complex object graph where every object uses the default inspect to cause that.



And in my very humble opinion this is fine, because the way I've always seen it is that `#inspect` is supposed to be something that gets used while debugging, not in production. E.g. my base assumption is: in production the common case is that `#inspect` is never called. (Unless some production debugging tool is using it explicitly)



The footgun happens when `#inspect` is combined with `NoMethodError`, which is definitely something that can happen in production, and can be triggered by both typos as well as (as pointed out above) duck/dynamic-typing bugs.



I like @mame 's PR since it avoids this issue in the default case, thus locking away the footgun. And it creates a new question -- how to get at this useful information while debugging?



@zverok 's idea of using `NoMethodError#detailed_message` seems interesting when combined with https://github.com/ruby/ruby/pull/6950. Maybe some kind of combination is an interesting answer for this issue?



----------------------------------------

Feature #18285: NoMethodError#message uses a lot of CPU/is really expensive to call

https://bugs.ruby-lang.org/issues/18285#change-101125



* Author: ivoanjo (Ivo Anjo)

* Status: Open

* Priority: Normal

----------------------------------------

Hello there! I'm working at Datadog on the ddtrace gem -- https://github.com/DataDog/dd-trace-rb and we ran into this issue on one of our internal testing applications. I also blogged about this issue in <https://ivoanjo.me/blog/2021/11/01/nomethoderror-ruby-cost/>.



### Background



While testing an application that threw a lot of `NoMethodError`s in a Rails controller (this was used for validation), we discovered that service performance was very much impacted when we were logging these exceptions. While investigating with a profiler, the performance impact was caused by calls to `NoMethodError#message`, because this Rails controller had a quite complex `#inspect` method, that was getting called every time we tried to get the `#message` from the exception.



### How to reproduce



```ruby

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



  def inspect # <-- expensive method gets called when calling NoMethodError#message

    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

```



### Expectation and result



Getting the `#message` from a `NoMethodError` should be no costly than getting it from any other exception.



In reality:



```

ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-linux]



no method error message cost

                        115.390  (� 1.7%) i/s -    580.000  in   5.027822s

runtime error message cost

                          6.938M (� 0.5%) i/s -     35.334M in   5.092617s



Comparison:

runtime error message cost:  6938381.6 i/s

no method error message cost:      115.4 i/s - 60130.02x  (� 0.00) slower

```



### Suggested solutions



1. Do not call `#inspect` on the object on which the method was not found (see <https://github.com/ruby/ruby/blob/e0915ba67964d843832148aeca29a1f8244ca7b1/error.c#L1962>)

2. Cache result of calling `#message` after the first call. Ideally this should be done together with suggestion 1.









-- 

https://bugs.ruby-lang.org/

 ______________________________________________
 ruby-core mailing list -- ruby-core@ml.ruby-lang.org
 To unsubscribe send an email to ruby-core-leave@ml.ruby-lang.org
 ruby-core info -- https://ml.ruby-lang.org/mailman3/postorius/lists/ruby-core.ml.ruby-lang.org/