https://bugs.ruby-lang.org/
https://bugs.ruby-lang.org/favicon.ico?1711330511
2021-04-02T14:21:45Z
Ruby Issue Tracking System
Ruby master - Bug #17772: Performance issue with NameError message in context with large instance variables (not caused by did_you_mean)
https://bugs.ruby-lang.org/issues/17772?journal_id=91260
2021-04-02T14:21:45Z
peterzhu2118 (Peter Zhu)
peter@peterzhu.ca
<ul></ul><p>The slowness is caused by a large amount of allocations required to build the error message. Consider the following script:</p>
<pre><code class="ruby syntaxhl" data-language="ruby"><span class="k">class</span> <span class="nc">Environment</span>
<span class="k">def</span> <span class="nf">run</span>
<span class="vi">@data</span> <span class="o">=</span> <span class="p">(</span><span class="mi">1</span><span class="o">..</span><span class="mi">5_000_000</span><span class="p">).</span><span class="nf">to_h</span> <span class="p">{</span><span class="o">|</span><span class="n">x</span><span class="o">|</span> <span class="p">[</span><span class="n">x</span><span class="p">,</span> <span class="n">x</span><span class="p">]}</span>
<span class="n">trigger_name_error</span>
<span class="k">rescue</span> <span class="no">Exception</span> <span class="o">=></span> <span class="n">e</span>
<span class="n">start</span> <span class="o">=</span> <span class="no">Time</span><span class="p">.</span><span class="nf">now</span>
<span class="nb">puts</span> <span class="s2">"GC before: </span><span class="si">#{</span><span class="no">GC</span><span class="p">.</span><span class="nf">stat</span><span class="si">}</span><span class="s2">"</span>
<span class="n">msg</span> <span class="o">=</span> <span class="n">e</span><span class="p">.</span><span class="nf">message</span>
<span class="nb">puts</span> <span class="s2">"GC after: </span><span class="si">#{</span><span class="no">GC</span><span class="p">.</span><span class="nf">stat</span><span class="si">}</span><span class="s2">"</span>
<span class="nb">puts</span> <span class="s2">"Length of error msg: </span><span class="si">#{</span><span class="n">msg</span><span class="p">.</span><span class="nf">length</span><span class="si">}</span><span class="s2">"</span>
<span class="nb">puts</span> <span class="s2">"First 1000 characters of error msg: </span><span class="si">#{</span><span class="n">msg</span><span class="p">[</span><span class="mi">0</span><span class="o">..</span><span class="mi">1000</span><span class="p">]</span><span class="si">}</span><span class="s2">"</span>
<span class="k">ensure</span>
<span class="nb">puts</span> <span class="s2">"In ensure after </span><span class="si">#{</span><span class="no">Time</span><span class="p">.</span><span class="nf">now</span> <span class="o">-</span> <span class="n">start</span><span class="si">}</span><span class="s2">"</span>
<span class="k">end</span>
<span class="k">end</span>
<span class="no">Environment</span><span class="p">.</span><span class="nf">new</span><span class="p">.</span><span class="nf">run</span>
</code></pre>
<p>We see the following output:</p>
<pre><code>GC before: {:count=>1148, :heap_allocated_pages=>50, :heap_sorted_length=>50, :heap_allocatable_pages=>0, :heap_available_slots=>20433, :heap_live_slots=>19333, :heap_free_slots=>1100, :heap_final_slots=>0, :heap_marked_slots=>16021, :heap_eden_pages=>50, :heap_tomb_pages=>0, :total_allocated_pages=>50, :total_freed_pages=>0, :total_allocated_objects=>5055539, :total_freed_objects=>5036206, :malloc_increase_bytes=>2320, :malloc_increase_bytes_limit=>16777216, :minor_gc_count=>1139, :major_gc_count=>9, :compact_count=>0, :read_barrier_faults=>0, :total_moved_objects=>0, :remembered_wb_unprotected_objects=>205, :remembered_wb_unprotected_objects_limit=>410, :old_objects=>15799, :old_objects_limit=>31598, :oldmalloc_increase_bytes=>2320, :oldmalloc_increase_bytes_limit=>65338462}
GC after: {:count=>5746, :heap_allocated_pages=>50, :heap_sorted_length=>50, :heap_allocatable_pages=>0, :heap_available_slots=>20433, :heap_live_slots=>16858, :heap_free_slots=>3575, :heap_final_slots=>0, :heap_marked_slots=>484, :heap_eden_pages=>50, :heap_tomb_pages=>0, :total_allocated_pages=>50, :total_freed_pages=>0, :total_allocated_objects=>25056407, :total_freed_objects=>25039549, :malloc_increase_bytes=>5200, :malloc_increase_bytes_limit=>33554432, :minor_gc_count=>5732, :major_gc_count=>14, :compact_count=>0, :read_barrier_faults=>0, :total_moved_objects=>0, :remembered_wb_unprotected_objects=>0, :remembered_wb_unprotected_objects_limit=>414, :old_objects=>365, :old_objects_limit=>31704, :oldmalloc_increase_bytes=>401962032, :oldmalloc_increase_bytes_limit=>134217728}
Length of error msg: 87777892
First 1000 characters of error msg: undefined local variable or method `trigger_name_error' for #<Environment:0x00007fde29027010 @data={1=>1, 2=>2, 3=>3, 4=>4, 5=>5, 6=>6, 7=>7, 8=>8, 9=>9, 10=>10, 11=>11, 12=>12, 13=>13, 14=>14, 15=>15, 16=>16, 17=>17, 18=>18, 19=>19, 20=>20, 21=>21, 22=>22, 23=>23, 24=>24, 25=>25, 26=>26, 27=>27, 28=>28, 29=>29, 30=>30, 31=>31, 32=>32, 33=>33, 34=>34, 35=>35, 36=>36, 37=>37, 38=>38, 39=>39, 40=>40, 41=>41, 42=>42, 43=>43, 44=>44, 45=>45, 46=>46, 47=>47, 48=>48, 49=>49, 50=>50, 51=>51, 52=>52, 53=>53, 54=>54, 55=>55, 56=>56, 57=>57, 58=>58, 59=>59, 60=>60, 61=>61, 62=>62, 63=>63, 64=>64, 65=>65, 66=>66, 67=>67, 68=>68, 69=>69, 70=>70, 71=>71, 72=>72, 73=>73, 74=>74, 75=>75, 76=>76, 77=>77, 78=>78, 79=>79, 80=>80, 81=>81, 82=>82, 83=>83, 84=>84, 85=>85, 86=>86, 87=>87, 88=>88, 89=>89, 90=>90, 91=>91, 92=>92, 93=>93, 94=>94, 95=>95, 96=>96, 97=>97, 98=>98, 99=>99, 100=>100, 101=>101, 102=>102, 103=>103, 104=>104, 105=>105, 106=>106, 107=>107, 108=>108, 109=>109, 110=>110, 111=>111, 112=>11
In ensure after 23.887575
</code></pre>
<p>Note the <code>:count</code> and <code>:total_allocated_objects</code> attributes. To generate the error message we allocated around 20 million objects and triggered the GC more than 4000 times.</p>
<p>Now, if we make <code>data</code> a local variable, we see the following output:</p>
<pre><code>GC before: {:count=>1150, :heap_allocated_pages=>50, :heap_sorted_length=>50, :heap_allocatable_pages=>0, :heap_available_slots=>20430, :heap_live_slots=>19890, :heap_free_slots=>540, :heap_final_slots=>0, :heap_marked_slots=>16021, :heap_eden_pages=>50, :heap_tomb_pages=>0, :total_allocated_pages=>50, :total_freed_pages=>0, :total_allocated_objects=>5055539, :total_freed_objects=>5035649, :malloc_increase_bytes=>2128, :malloc_increase_bytes_limit=>16777216, :minor_gc_count=>1141, :major_gc_count=>9, :compact_count=>0, :read_barrier_faults=>0, :total_moved_objects=>0, :remembered_wb_unprotected_objects=>205, :remembered_wb_unprotected_objects_limit=>410, :old_objects=>15799, :old_objects_limit=>31598, :oldmalloc_increase_bytes=>2128, :oldmalloc_increase_bytes_limit=>65338462}
GC after: {:count=>1151, :heap_allocated_pages=>50, :heap_sorted_length=>50, :heap_allocatable_pages=>0, :heap_available_slots=>20430, :heap_live_slots=>18515, :heap_free_slots=>1915, :heap_final_slots=>0, :heap_marked_slots=>16144, :heap_eden_pages=>50, :heap_tomb_pages=>0, :total_allocated_pages=>50, :total_freed_pages=>0, :total_allocated_objects=>5056405, :total_freed_objects=>5037890, :malloc_increase_bytes=>6448, :malloc_increase_bytes_limit=>16777216, :minor_gc_count=>1142, :major_gc_count=>9, :compact_count=>0, :read_barrier_faults=>0, :total_moved_objects=>0, :remembered_wb_unprotected_objects=>205, :remembered_wb_unprotected_objects_limit=>410, :old_objects=>15891, :old_objects_limit=>31598, :oldmalloc_increase_bytes=>25328, :oldmalloc_increase_bytes_limit=>65338462}
Length of error msg: 93
First 1000 characters of error msg: undefined local variable or method `trigger_name_error' for #<Environment:0x00007fa274812f68>
In ensure after 0.013302
</code></pre>
<p>Note that the GC only ran once and allocated less than 1000 objects. The difference is that the outputted error message does not have the <code>@data</code> instance variable in the output (error message is about 87 million characters with <code>@data</code> vs. 93 characters without).</p>
Ruby master - Bug #17772: Performance issue with NameError message in context with large instance variables (not caused by did_you_mean)
https://bugs.ruby-lang.org/issues/17772?journal_id=92695
2021-06-29T16:49:44Z
jeremyevans0 (Jeremy Evans)
merch-redmine@jeremyevans.net
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Rejected</i></li></ul>