From: peter@... Date: 2021-04-02T14:21:46+00:00 Subject: [ruby-core:103185] [Ruby master Bug#17772] Performance issue with NameError message in context with large instance variables (not caused by did_you_mean) Issue #17772 has been updated by peterzhu2118 (Peter Zhu). The slowness is caused by a large amount of allocations required to build the error message. Consider the following script: ```ruby 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 #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 # 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). ---------------------------------------- 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#change-91260 * Author: Confusion (Ivo Wever) * Status: Open * Priority: Normal * 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 ---------------------------------------- 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? -- https://bugs.ruby-lang.org/ Unsubscribe: