sheap-vanity.md

Investigating memory growth with Sheap in a Rails application.

Ran this locally because of an issue with rbtrace not working with Puma when requests aren't actively arriving:

while true; do
  status_code=$(curl -o /dev/null -s -w "%{http_code}\n" -I "https://dayoftheshirt.com")
  echo "Status code: $status_code"
  sleep 1
done

Then on remote box:

# enable fancy data
bundle exec rbtrace --pid $PID --eval 'ObjectSpace.trace_object_allocations_start'

# get the PID
ps
PID=9

# 3 times
bundle exec rbtrace --pid $PID --eval 'filename = "/tmp/ruby-heap.#{Time.now.to_i}.dump"; Thread.new { require "objspace"; GC.start; io=File.open(filename, "w"); ObjectSpace.dump_all(output: io); io.close; puts io }; filename'

Then with the dumps:

# $ bundle exec irb
require 'sheap'

$diff = Sheap::Diff.new( "/tmp/ruby-heap.1718719322.dump", "/tmp/ruby-heap.1718719379.dump", "/tmp/ruby-heap.1718719418.dump")

$diff.retained.select(&:old?).group_by(&:type_str).transform_values { |objects| objects.map(&:memsize).sum }.sort_by { |k,v| v }.to_h
=> 
{"SHAPE"=>0,
 "FILE"=>0,
 "SYMBOL"=>160,
 "ICLASS"=>320,
 "STRUCT"=>1200,
 "CLASS"=>4240,
 "MATCH"=>14664,
 "IMEMO"=>24624,
 "ARRAY"=>259248,
 "DATA"=>652728,
 "OBJECT"=>1042280,
 "STRING"=>1687515,
 "HASH"=>3464544}
 
$diff.retained.select(&:old?).group_by { |o| "#{o.file}:#{o.line}" }.transform_values { |objects| objects.map(&:memsize).sum }.sort_by { |k,v| v }.reverse.first(10).to_h
=> 
{"/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:72"=>
  593653,
 "/usr/local/bundle/ruby/3.3.0/gems/skylight-6.0.4/lib/skylight/extensions/source_location.rb:138"=>474200,
 "/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:640"=>467200,
 "/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/core_ext/string/output_safety.rb:76"=>
  363146,
 "/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/result.rb:169"=>335520,
 "/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/associations.rb:320"=>232720,
 "/usr/local/bundle/ruby/3.3.0/gems/activemodel-7.1.3.4/lib/active_model/attribute_set/builder.rb:28"=>215520,
 "/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/associations.rb:339"=>199680,
 "/usr/local/bundle/ruby/3.3.0/gems/activemodel-7.1.3.4/lib/active_model/attribute_set/builder.rb:22"=>198912,
 "/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/core_ext/string/output_safety.rb:72"=>
  193032}
  
# What are these persistence objects
  
irb(main):013> $diff.retained.select { |o| o.file == "/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb" && o.line == 640 }.first
=> 
#<OBJECT 0x7edd550ef658
 type="OBJECT",
 shape_id=4872,
 slot_size=320,
 class=#<CLASS 0x7edd613bc1e0 Shirt (683 refs)>,
 embedded=true,
 ivars=26,
 references=(4 refs),
 file="/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb",
 line=640,
 method="allocate",
 generation=5435,
 memsize=320,
 flags=wb_protected|old|uncollectible|marked>
 
 # A SHIRT!?!?! That's bad. And it's old/uncollectible.
 
 # Ok where is this coming from
 
 irb(main):020> $diff.after.at("0x7edd53545560").inverse_references
=> [#<OBJECT 0x7edd58efd490 Shirt::ActiveRecord_Relation (5 refs)>]
irb(main):021> $diff.after.at("0x7edd53545560").inverse_references.first.inverse_references
=> [#<OBJECT 0x7edd550de9c0 InsightsController (15 refs)>]
irb(main):022> $diff.after.at("0x7edd53545560").inverse_references.first.inverse_references.first
=> 
#<OBJECT 0x7edd550de9c0
 type="OBJECT",
 shape_id=6545,
 slot_size=320,
 class=#<CLASS 0x7edd6107eed8 InsightsController (251 refs)>,
 embedded=true,
 ivars=20,
 references=(15 refs),
 file="/usr/local/bundle/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal.rb",
 line=309,
 method="new",
 generation=5435,
 memsize=320,
 flags=wb_protected|old|uncollectible|marked>
 
# Huh, a controller instance that's old. And holding onto all of the records it loads. What's its root path?
 
controller = $diff.after.at("0x7edd53545560")
irb(main):090> $diff.after.find_path(controller)
=> 
[#<ROOT vm  (2960 refs)>,
 #<CLASS 0x7edd8612fd30 Object (828 refs)>,
 #<CLASS 0x7edd6107eed8 InsightsController (251 refs)>,
 #<IMEMO 0x7edd558f4088 ment (3 refs)>,
 #<DATA 0x7edd558f40b0 proc (3 refs)>,
 #<IMEMO 0x7edd558f41a0 env (4 refs)>,
 #<OBJECT 0x7edd550de9c0 InsightsController (15 refs)>]
 
 # What are these IMEMO and procs?
 
 irb(main):096> $diff.after.at("0x7edd558f4088")
=> 
#<IMEMO 0x7edd558f4088
 type="IMEMO",
 shape_id=0,
 slot_size=40,
 imemo_type="ment",
 references=(3 refs),
 file="/usr/local/bundle/ruby/3.3.0/gems/vanity-4.0.4/lib/vanity/vanity.rb",
 line=65,
 method="define_method",
 generation=5435,
 memsize=48,
 flags=wb_protected|old|uncollectible|marked>
 
 # VANITY!
 
irb(main):097> $diff.after.at("0x7edd558f40b0")
=> 
#<DATA 0x7edd558f40b0
 type="DATA",
 shape_id=0,
 slot_size=40,
 class=#<CLASS 0x7edd860fd2b8 Proc (80 refs)>,
 struct="proc",
 references=(3 refs),
 file="/usr/local/bundle/ruby/3.3.0/gems/vanity-4.0.4/lib/vanity/vanity.rb",
 line=65,
 method="define_method",
 generation=5435,
 memsize=80,
 flags=wb_protected|old|uncollectible|marked>

A define_method ?!! So I open up this method in Vanity:

# Sets the Vanity context. For example, when using Rails this would be
# set by the set_vanity_context before filter (via Vanity::Rails#use_vanity).
def self.context=(context)
  Thread.current[:vanity_context] = context

  if context
    context.class.send(:define_method, :vanity_add_to_active_experiments) do |name, alternative|
      @_vanity_experiments ||= {}
      @_vanity_experiments[name] ||= alternative
      @_vanity_experiments[name].value
    end
    context.class.send(:alias_method, :vanity_store_experiment_for_js, :vanity_add_to_active_experiments)

    context.class.send(:define_method, :vanity_active_experiments) do
      @_vanity_experiments ||= {}
    end
  end

  context
end

And it seems like the context which is a controller instance, is being retained because it's in the state that's bound into the block that's created in those define_method calls

I'm a vanity maintainer, but also looks like the project was (finally) archived, so I guess I need to remove it entirely and find a replacement.