Ruby » Ruby master

Feature #18285

Updated by ivoanjo (Ivo Anjo) over 2 years ago

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. 

Back