https://bugs.ruby-lang.org/https://bugs.ruby-lang.org/favicon.ico?17113305112015-05-09T07:02:44ZRuby Issue Tracking SystemRuby master - 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 exceptionhttps://bugs.ruby-lang.org/issues/11088?journal_id=523582015-05-09T07:02:44Zshishir127 (Shishir Joshi)shishir127@gmail.com
<ul><li><strong>File</strong> <a href="/attachments/5207">11088_test.rb</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/5207/11088_test.rb">11088_test.rb</a> added</li></ul><p>Hi Jurgen,</p>
<p>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?</p>
<p>Also, according to the documentation for Marshall (<a href="http://ruby-doc.org/core-2.2.2/Marshal.html#method-c-dump" class="external">http://ruby-doc.org/core-2.2.2/Marshal.html#method-c-dump</a>)</p>
<blockquote>
<p>Marshal can't dump following objects:</p>
<p>anonymous Class/Module.</p>
<p>objects which are related to system (ex: Dir, File::Stat, IO, File, Socket and so on)</p>
<p>an instance of MatchData, Data, Method, UnboundMethod, Proc, Thread, ThreadGroup, Continuation</p>
<p>objects which define singleton methods</p>
</blockquote> Ruby master - 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 exceptionhttps://bugs.ruby-lang.org/issues/11088?journal_id=523592015-05-10T02:45:46Zaustin (Austin Ziegler)halostatue@gmail.com
<ul><li><strong>File</strong> <a href="/attachments/5212">simple-inspect.txt</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/5212/simple-inspect.txt">simple-inspect.txt</a> added</li><li><strong>File</strong> <a href="/attachments/5213">simple-inspect-stats.txt</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/5213/simple-inspect-stats.txt">simple-inspect-stats.txt</a> added</li><li><strong>File</strong> <a href="/attachments/5215">bug_hunt_benchmark.rb</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/5215/bug_hunt_benchmark.rb">bug_hunt_benchmark.rb</a> added</li><li><strong>File</strong> <a href="/attachments/5217">bug_hunt_simple.rb</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/5217/bug_hunt_simple.rb">bug_hunt_simple.rb</a> added</li></ul><p>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:</p>
<ul>
<li>52 appear between 2x and 9x.</li>
<li>17 appear between 20x and 29x.</li>
<li>13 appear between 30x and 39x.</li>
<li>6 appear between 40x and 49x.</li>
<li>16 appear between 50x and 59x.</li>
<li>9 appear between 60x and 69x.</li>
<li>1 appears 71x.</li>
<li>1 appears 88x.</li>
<li>1 appears 89x.</li>
</ul>
<p>I’m attaching <code>bug_hunt_simple.rb</code> (based on <code>SimpleInspect</code> below), <code>simple-inspect.txt</code> (the output of a simplified inspect), and <code>simple-inspect-stats.txt</code> (the count of appearances).</p>
<p>What’s interesting to me is that there’s an <em>observable</em> slowdown in the output of the <code>NoMethodError</code> result, so I benchmarked it (<code>bug_hunt_benchmark.rb</code>). 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.)</p>
<blockquote>
<p>Note: these are the values where the inspect strings are constructed. If I remove the custom string construction and minimize the interaction with <code>$__inspected__</code> and its helper methods, there is <em>still</em> a consistent 0.05–0.1s/100k slowdown.</p>
</blockquote>
<p>So there’s something about looking at an exception that triggers an expensive <code>#inspect</code>—but then discards it for a cheap <code>#inspect</code> in some circumstances. Without the <code>SimpleInspect</code> module (which is mostly useless because it keeps program-wide state, but is useful for this investigation), somehow the recursion detection of <code>#inspect</code> 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).</p>
<pre><code class="ruby syntaxhl" data-language="ruby"><span class="k">module</span> <span class="nn">SimpleInspect</span>
<span class="k">def</span> <span class="nf">inspect</span>
<span class="n">result</span> <span class="o">=</span> <span class="k">if</span> <span class="n">inspected?</span>
<span class="s2">"#<%s (%d) ...>"</span> <span class="o">%</span> <span class="p">[</span> <span class="n">inspected_key</span><span class="p">,</span> <span class="n">inspected_count</span> <span class="p">]</span>
<span class="k">else</span>
<span class="k">super</span>
<span class="k">end</span>
<span class="nb">inspect</span><span class="o">!</span>
<span class="s2">"</span><span class="se">\n</span><span class="s2">"</span> <span class="o">+</span> <span class="n">result</span>
<span class="k">end</span>
<span class="kp">private</span>
<span class="k">def</span> <span class="nf">inspected?</span>
<span class="n">inspected</span><span class="p">[</span><span class="n">inspected_key</span><span class="p">].</span><span class="nf">nonzero?</span>
<span class="k">end</span>
<span class="k">def</span> <span class="nf">inspect!</span>
<span class="n">inspected</span><span class="p">[</span><span class="n">inspected_key</span><span class="p">]</span> <span class="o">+=</span> <span class="mi">1</span>
<span class="k">end</span>
<span class="k">def</span> <span class="nf">inspected_count</span>
<span class="n">inspected</span><span class="p">[</span><span class="n">inspected_key</span><span class="p">]</span>
<span class="k">end</span>
<span class="k">def</span> <span class="nf">inspected</span>
<span class="vg">$__inspected__</span> <span class="o">||=</span> <span class="no">Hash</span><span class="p">.</span><span class="nf">new</span> <span class="p">{</span> <span class="o">|</span><span class="n">h</span><span class="p">,</span> <span class="n">k</span><span class="o">|</span> <span class="n">h</span><span class="p">[</span><span class="n">k</span><span class="p">]</span> <span class="o">=</span> <span class="mi">0</span> <span class="p">}</span>
<span class="k">end</span>
<span class="k">def</span> <span class="nf">inspected_key</span>
<span class="s2">"%s:0x%014x"</span> <span class="o">%</span> <span class="p">[</span> <span class="nb">self</span><span class="p">.</span><span class="nf">class</span><span class="p">,</span> <span class="s2">"0x%014x"</span> <span class="o">%</span> <span class="p">(</span><span class="nb">object_id</span> <span class="o">*</span> <span class="mi">2</span><span class="p">)</span> <span class="p">]</span>
<span class="k">end</span>
<span class="k">end</span>
<span class="k">class</span> <span class="nc">Object</span>
<span class="kp">include</span> <span class="no">SimpleInspect</span>
<span class="k">end</span>
</code></pre> Ruby master - 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 exceptionhttps://bugs.ruby-lang.org/issues/11088?journal_id=523602015-05-10T02:48:33Znobu (Nobuyoshi Nakada)nobu@ruby-lang.org
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Rejected</i></li></ul><p>Your objects are consist of very large networks with complex recursive references.<br>
Even with omission of the recursions, it makes tons of hundreds MB strings.<br>
You should define <code>inspect</code> methods for your purpose.</p> Ruby master - 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 exceptionhttps://bugs.ruby-lang.org/issues/11088?journal_id=523622015-05-10T02:58:40Zaustin (Austin Ziegler)halostatue@gmail.com
<ul></ul><p>I don't think this should be rejected completely, Nobu. As I mentioned in<br>
my analysis, it appears that NoMethodError#message is calling #inspect on<br>
the object that raised the error, only to discard <em>most</em> of the item in<br>
favour of <em>just</em> the "#<a href="Klass:0xOBJECTREF" class="external">Klass:0xOBJECTREF</a>" output. I can understand that<br>
this is a pathological case, but I'm curious why the output is different<br>
than would be expected here.</p>
<p>-a</p>
<p>On Sat, May 9, 2015 at 10:48 PM <a href="mailto:nobu@ruby-lang.org" class="email">nobu@ruby-lang.org</a> wrote:</p>
<blockquote>
<p>Issue <a class="issue tracker-1 status-6 priority-4 priority-default closed" title="Bug: On Exception too expensive inspect is called on recursive object graph with 3000 elements in it, ... (Rejected)" href="https://bugs.ruby-lang.org/issues/11088">#11088</a> has been updated by Nobuyoshi Nakada.</p>
<p>Status changed from Open to Rejected</p>
<p>Your objects are consist of very large networks with complex recursive<br>
references.<br>
Even with omission of the recursions, it makes tons of hundreds MB strings.<br>
You should define <code>inspect</code> methods for your purpose.</p>
<hr>
<p>Bug <a class="issue tracker-1 status-6 priority-4 priority-default closed" title="Bug: On Exception too expensive inspect is called on recursive object graph with 3000 elements in it, ... (Rejected)" href="https://bugs.ruby-lang.org/issues/11088">#11088</a>: Infinite loop on calling missing/overwritten methods of<br>
restored marshaled objects<br>
<a href="https://bugs.ruby-lang.org/issues/11088#change-52360" class="external">https://bugs.ruby-lang.org/issues/11088#change-52360</a></p>
<ul>
<li>Author: Jürgen Bickert</li>
<li>Status: Rejected</li>
<li>Priority: Normal</li>
<li>Assignee:</li>
<li>ruby -v: ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]</li>
<li>Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN</li>
</ul>
<hr>
<p>I have Marshal.dump some objects and then I Marshal.load them and later I<br>
call non-existent methods on those objects and instead of raising an<br>
exception (NoMethodError) it runs off in an infinite loop.</p>
<p>I have tested with simple cases where the dumped structure is not<br>
recursive and it works fine. So I attached a non-working dump which will<br>
when called with inspect or a non-existing method run off in an infinite<br>
loop.</p>
<p>When you run "ruby bug_hunt.rb" it will get stuck and you have to<br>
abort(CTRL-C) and only then will it print an error message and finish.</p>
<p>---Files--------------------------------<br>
bug_hunt.rb (336 Bytes)<br>
ruby_object.dump (561 KB)<br>
11088_test.rb (305 Bytes)<br>
simple-inspect.txt (1.19 MB)<br>
simple-inspect-stats.txt (90.7 KB)<br>
bug_hunt_benchmark.rb (1.42 KB)<br>
bug_hunt_simple.rb (1.09 KB)</p>
<p>--<br>
<a href="https://bugs.ruby-lang.org/" class="external">https://bugs.ruby-lang.org/</a></p>
</blockquote> Ruby master - 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 exceptionhttps://bugs.ruby-lang.org/issues/11088?journal_id=534092015-07-15T09:52:09Zkaiserprogrammer (Jürgen Bickert)kaiserprogrammer@gmail.com
<ul><li><strong>Subject</strong> changed from <i>Infinite loop on calling missing/overwritten methods of restored marshaled objects</i> to <i>On Exception too expensive inspect is called on recursive object graph with 3000 elements in it, swallows memory and ultimately doesn't deliver exception</i></li><li><strong>Description</strong> updated (<a title="View differences" href="/journals/53409/diff?detail_id=38438">diff</a>)</li></ul><p>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.</p>