Project

General

Profile

Actions

Feature #18285

closed

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

Added by ivoanjo (Ivo Anjo) over 2 years ago. Updated 3 months ago.

Status:
Closed
Assignee:
-
Target version:
-
[ruby-core:105909]

Description

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 NoMethodErrors 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

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.

Related issues 7 (3 open4 closed)

Related to Ruby master - Feature #6733: New inspect frameworkOpenActions
Related to Ruby master - Bug #6291: Backtrace printout halts for an extremely long time when large amounts of data are allocatedClosedmatz (Yukihiro Matsumoto)04/14/2012Actions
Related to Ruby master - Feature #6783: Infinite loop in inspect, not overriding inspect, to_s, and no known circular references. Stepping into inspect in debugger locks it up with 100% CPU.OpenActions
Related to Ruby master - Feature #19520: Support for `Module.new(name)` and `Class.new(superclass, name)`.RejectedActions
Has duplicate Ruby master - Bug #19065: ruby 3.1.2 is printing all class variables for undefined errorClosedActions
Has duplicate Ruby master - Feature #19978: NoMethodError and large objects should not create unwieldy error messagesClosedActions
Is duplicate of Ruby master - Feature #9725: Do not inspect NameError target object unless verboseOpenActions
Actions

Also available in: Atom PDF

Like1
Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like2Like0Like0Like0Like0Like0Like0Like1Like0