From: "ivoanjo (Ivo Anjo)" Date: 2021-11-03T09:15:01+00:00 Subject: [ruby-core:105915] [Ruby master Misc#18285] NoMethodError#message uses a lot of CPU/is really expensive to call Issue #18285 has been updated by ivoanjo (Ivo Anjo). #### Important note! I'm actually talking about **`NoMethodError`**, not **`NameError`**, so I don't think this issue is caused by the did you mean gem behavior (which I really like). This may have been confusing because both of them share the `NameError::message` class where the actual call to `#inspect` lives. > Let me confirm: you are facing this issue when testing dd-trace-rb, not in production, right? I cannot imagine how NameError#message is called so many times in production. Apologies for the confusion. I meant that we were simulating what if a production Rails application had a bug (in this case, mistakenly called a method that had been deleted), and how dd-trace-rb would help customers debug such an issue. I think it's reasonable assertion to say this can happen -- people will do these kinds of mistakes, and if they're not paying attention to their logs/alarms/error tracking data, their app can be impacted by such an issue for a while until they realize what's going on and have the chance to deploy a fix. --- In my view, part of the problem here is that on classes with a big `#inspect`, the call to `#inspect` ends up being completely useless on Ruby 2.7 and below: ```ruby > puts RUBY_DESCRIPTION ruby 2.7.4p191 (2021-07-07 revision a21a3b7d23) [x86_64-darwin19] > class Foo; def inspect; puts 'inspect called!'; 'A' * 65; end; end > Foo.new.foo inspect called! # => NoMethodError: undefined method `foo' for AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA:Foo > class Foo; def inspect; puts 'inspect called!'; 'A' * 66; end; end > Foo.new.foo inspect called! # => NoMethodError: undefined method `foo' for # ``` When I was testing, I wasn't seeing the result of the `#inspect`, so it wasn't even occurring to me what was going on (and this is what confused me even further). I realize now that the limit was removed in 3.0 (https://bugs.ruby-lang.org/issues/16832 and https://github.com/ruby/ruby/pull/3090) so in 3.0 it always shows the whole string, which can be a whole another problem as well, because people may not be expecting a `NoMethodError` to contain a small novel in its `#message`. So what I'm asking upstream to consider is: *Could we simplify `NoMethodError` to not include the `#inspect`? According to the PR above, the previous limit was in place for about 24 years and it looks like nobody really complained that they couldn't see their `#inspect` on objects which had a complex one.* ---------------------------------------- Misc #18285: NoMethodError#message uses a lot of CPU/is really expensive to call https://bugs.ruby-lang.org/issues/18285#change-94458 * 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 . ### 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 ) 2. Cache result of calling `#message` after the first call. Ideally this should be done together with suggestion 1. -- https://bugs.ruby-lang.org/ Unsubscribe: