From: "zverok (Victor Shepelev) via ruby-core" <ruby-core@...>
Date: 2023-01-05T18:42:58+00:00
Subject: [ruby-core:111660] [Ruby master Feature#18285] NoMethodError#message uses a lot of CPU/is really expensive to call

Issue #18285 has been updated by zverok (Victor Shepelev).





@byroot I am not denying the problem exists or saying it shouldn't be handled (and I acknowledge my Rails remark was inappropriate).



I am just saying that the way of fixing it by replacing the object representation with class name breaks many good use cases and, in general, seems less friendly to me.

It always felt nice and informative.



Interesting to note that the latest Ruby releases tend to add _more_ context for errors (with `did_you_mean` and `error_highlight`), and it is considered a good thing, while this change seems to go in the exactly opposite direction.



Actually, thinking a bit more about this, maybe a good compromise solution would be to preserve this change but add `#inspect` of the object to `NoMethodError#detailed_message`?.. It seems to be introduced exactly to handle the balance between the efficiency/brevity of the "core" message and helpfulness.



As for the problems which `#inspect` in (any) error message leads to, I believe there are two related but different ones?

1. What if `#inspect` output is too long? Intuitively, I would say that there are many techniques of mechanical shortening of the string to the desired limit. Say, modern IRB handles it quite gracefully (this is a copy-paste of FULL IRB session, the `...` is what it did):

  ```

  >> ary = [{a: 1, foo: :bar}] * 100

  => 

  [{:a=>1, :foo=>:bar},                                                              

  ...                           

  ```

2. What if `#inspect` is very inefficient? In this case a) actually, yes, I believe that it is client's code responsibility (and it is not "sharp knife"-class responsibility, it is rather "if you've implemented `to_s` to return a number, nothing would work properly"), but b) maybe the `detailed_message` idea helps mitigating this, anyway?.. 



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

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

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



* 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/