Bug #17772: Performance issue with NameError message in context with large instance variables (not caused by did_you_mean)

• Status: Rejected
• Assignee: -
• Target version: -
• ruby -v: ruby 2.7.2p137 (2020-10-01 revision 5445e04352) [x86_64-linux]
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

[Confusion (Ivo Wever)]

The following script takes about 2 seconds (tested on 2.6.6 and 2.7.2) to get from 'rescue' to 'ensure' on my machine, when executed as ruby --disable-did_you_mean script.rb. The time is taken by getting the e.message.

class Environment                                                               
  def run                                                                       
    @data = (1..5_000_000).to_h {|x| [x, x]}                                    
    trigger_name_error                                                          
  rescue Exception => e                                                         
    start = Time.now                                                            
    e.message                                                             
  ensure                                                                                                                                                                     
    puts "In ensure after #{Time.now - start}"                                  
  end                                                                           
end                                                                             
                                                                                
Environment.new.run                

The time is much lower if you:

• change the instance variable to a local variable
• change #run to a class method
• trigger something other than a NameError

The time is roughly linear in the size of @data.

The time roughly doubles if you enable did_you_mean.

Since I'm regularly operating in such contexts with large instance variables, I noted the slowness of NameErrors and went looking for the cause, whittling it down to the above script. Not sure if this should be considered a bug, but I guess it is probably undesirable?

[peterzhu2118 (Peter Zhu)]

The slowness is caused by a large amount of allocations required to build the error message. Consider the following script:

class Environment
  def run
    @data = (1..5_000_000).to_h {|x| [x, x]}
    trigger_name_error
  rescue Exception => e
    start = Time.now
    puts "GC before: #{GC.stat}"
    msg = e.message
    puts "GC after: #{GC.stat}"
    puts "Length of error msg: #{msg.length}"
    puts "First 1000 characters of error msg: #{msg[0..1000]}"
  ensure
    puts "In ensure after #{Time.now - start}"
  end
end

Environment.new.run

We see the following output:

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

Note the :count and :total_allocated_objects attributes. To generate the error message we allocated around 20 million objects and triggered the GC more than 4000 times.

Now, if we make data a local variable, we see the following output:

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

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 @data instance variable in the output (error message is about 87 million characters with @data vs. 93 characters without).

[jeremyevans0 (Jeremy Evans)]

• Status changed from Open to Rejected