Bug #11088: On Exception too expensive inspect is called on recursive object graph with 3000 elements in it, swallows memory and ultimately doesn't deliver exception

• Status: Rejected
• Assignee: -
• Target version: -
• ruby -v: ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]
• Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN

[kaiserprogrammer (Jürgen Bickert)]

I have tested with simple cases where the dumped structure is not recursive and it works fine. So I attached a non-working dump which will when called with inspect or a non-existing method run off in an infinite loop.

When you run "ruby bug_hunt.rb" it will get stuck and you have to abort(CTRL-C) and only then will it print an error message and finish.

[shishir127 (Shishir Joshi)]

• File 11088_test.rb 11088_test.rb added

Hi Jurgen,

I executed bug_hunt.rb and I was able to reproduce this issue. But when I tried a simple test (attached in 11088_test.rb) I did not see this bug. Can you tell us how you generated the ruby_object.dump? Do you have code for it?

Also, according to the documentation for Marshall (http://ruby-doc.org/core-2.2.2/Marshal.html#method-c-dump)

Marshal can't dump following objects:

anonymous Class/Module.

objects which are related to system (ex: Dir, File::Stat, IO, File, Socket and so on)

an instance of MatchData, Data, Method, UnboundMethod, Proc, Thread, ThreadGroup, Continuation

objects which define singleton methods

[austin (Austin Ziegler)]

• File simple-inspect.txt simple-inspect.txt added
• File simple-inspect-stats.txt simple-inspect-stats.txt added
• File bug_hunt_benchmark.rb bug_hunt_benchmark.rb added
• File bug_hunt_simple.rb bug_hunt_simple.rb added

The data structure in question is large and has some slightly pathological recursiveness. There are 3,204 objects marshalled. Most of these (3,088) are referenced exactly once. Of the remaining:

• 52 appear between 2x and 9x.
• 17 appear between 20x and 29x.
• 13 appear between 30x and 39x.
• 6 appear between 40x and 49x.
• 16 appear between 50x and 59x.
• 9 appear between 60x and 69x.
• 1 appears 71x.
• 1 appears 88x.
• 1 appears 89x.

I’m attaching bug_hunt_simple.rb (based on SimpleInspect below), simple-inspect.txt (the output of a simplified inspect), and simple-inspect-stats.txt (the count of appearances).

What’s interesting to me is that there’s an observable slowdown in the output of the NoMethodError result, so I benchmarked it (bug_hunt_benchmark.rb). There’s a consistent 0.1–0.2 second slowdown over 100,000 iterations, and the output of the exception message differs between the two forms (at the bottom of the file). (The slowdown is ~0.6s/100k on ruby 2.0 and 2.1, so there is that.)

Note: these are the values where the inspect strings are constructed. If I remove the custom string construction and minimize the interaction with $__inspected__ and its helper methods, there is still a consistent 0.05–0.1s/100k slowdown.

So there’s something about looking at an exception that triggers an expensive #inspect—but then discards it for a cheap #inspect in some circumstances. Without the SimpleInspect module (which is mostly useless because it keeps program-wide state, but is useful for this investigation), somehow the recursion detection of #inspect has been blown to bits in some recent version of Ruby (the problem shows up for ruby 2.0.0p481, ruby 2.1.6p336, ruby 2.2.2p95 and ruby 2.3.0dev (2015-04-11), which are the only Rubies I have on my Mac right now).

module SimpleInspect
  def inspect
    result = if inspected?
               "#<%s (%d) ...>" % [ inspected_key, inspected_count ]
             else
               super
             end
    inspect!
    "\n" + result
  end

  private
  def inspected?
    inspected[inspected_key].nonzero?
  end

  def inspect!
    inspected[inspected_key] += 1
  end

  def inspected_count
    inspected[inspected_key]
  end

  def inspected
    $__inspected__ ||= Hash.new { |h, k| h[k] = 0 }
  end

  def inspected_key
    "%s:0x%014x" % [ self.class, "0x%014x" % (object_id * 2) ]
  end
end

class Object
  include SimpleInspect
end

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Rejected

Your objects are consist of very large networks with complex recursive references.
Even with omission of the recursions, it makes tons of hundreds MB strings.
You should define inspect methods for your purpose.

[austin (Austin Ziegler)]

I don't think this should be rejected completely, Nobu. As I mentioned in
my analysis, it appears that NoMethodError#message is calling #inspect on
the object that raised the error, only to discard most of the item in
favour of just the "#Klass:0xOBJECTREF" output. I can understand that
this is a pathological case, but I'm curious why the output is different
than would be expected here.

-a

On Sat, May 9, 2015 at 10:48 PM [e-mail] wrote:

Issue #11088 has been updated by Nobuyoshi Nakada.

Status changed from Open to Rejected

Your objects are consist of very large networks with complex recursive
references.
Even with omission of the recursions, it makes tons of hundreds MB strings.
You should define inspect methods for your purpose.

---

Bug #11088: Infinite loop on calling missing/overwritten methods of
restored marshaled objects
https://bugs.ruby-lang.org/issues/11088#change-52360

• Author: Jürgen Bickert
• Status: Rejected
• Priority: Normal
• Assignee:
• ruby -v: ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]
• Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN

---

I have Marshal.dump some objects and then I Marshal.load them and later I
call non-existent methods on those objects and instead of raising an
exception (NoMethodError) it runs off in an infinite loop.

I have tested with simple cases where the dumped structure is not
recursive and it works fine. So I attached a non-working dump which will
when called with inspect or a non-existing method run off in an infinite
loop.

When you run "ruby bug_hunt.rb" it will get stuck and you have to
abort(CTRL-C) and only then will it print an error message and finish.

---Files--------------------------------
bug_hunt.rb (336 Bytes)
ruby_object.dump (561 KB)
11088_test.rb (305 Bytes)
simple-inspect.txt (1.19 MB)
simple-inspect-stats.txt (90.7 KB)
bug_hunt_benchmark.rb (1.42 KB)
bug_hunt_simple.rb (1.09 KB)

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

[kaiserprogrammer (Jürgen Bickert)]

• Subject changed from Infinite loop on calling missing/overwritten methods of restored marshaled objects to On Exception too expensive inspect is called on recursive object graph with 3000 elements in it, swallows memory and ultimately doesn't deliver exception
• Description updated (diff)

After your input and directing me to inspect, I did some more testing and found that marshal has absolutely nothing to do with this problem. Writing custom inspect methods fixes the problem. Another question still remains for why is inspect called on the errored object, development stagnated for me because my program has a moderately sized object graph with recursive dependencies. I couldn't get any error messages at all anymore! Imagine you mistyped a method but your process will hang in inspect instead of finally raising NoMethodError exception to the toplevel.