Hunting memory ghosts

Basic memory profiling in Ruby with MRI

Transcript

1. Hunting memory ghosts Jose Luis Salas Flywire
2. # whoami • Jose Luis Salas • SRE at Flywire • twitter: @josacar • github: josacar
3. What’s a memory leak A memory leak is a type of resource leak that occurs when a computer program incorrectly manages memory allocations in such a way that memory which is no longer needed is not released. Source: Wikipedia
4. Leaking memory in MRI • Leaking objects in Ruby heap • Leaking memory in C structures
5. How find C leaks • gdb • valgrind / leaks • pprof • jemalloc • printf in C code
6. Leak in C extensions • eventmachine#585
 
 
 
 
 • redcarpet#516
 
 
 
 

7. Leaks in Ruby code
8. How find ruby leaks • Use `rbtrace` gem • Use `allocation_tracer` gem • Use `objspace` stdlib • Use gdb
9. Get objects by class require ‘objspace’ Thread.new do GC.start objs = Hash.new(0) ObjectSpace.each_object do |obj| objs[obj.class] += 1 end obj_sorted_desc = objs.sort_by { |_,v| -v } top_ten = obj_sorted_desc.first(10) $stderr.puts top_ten end
10. $ bundle exec rbtrace -p PID -e 'Thread.new{ GC.start; objs = Hash.new(0); ObjectSpace.each_object {|o| objs[o.class] += 1}; $stderr.puts( objs.sort_by { | _,v| -v }.first(5) )}' • String 92800 • Array 24709 • RubyVM::InstructionSequence 17067 • Proc 5051 • RubyVM::Env 5000 • String 92562 • Array 25042 • RubyVM::InstructionSequence 17067 • RubyVM::Env 5566 • String 92675 • Array 25388 • RubyVM::InstructionSequence 17067 • RubyVM::Env 5949 • Proc 5871 • String 92547 • Array 26287 • RubyVM::InstructionSequence 17067 • RubyVM::Env 7165 • Proc 6916
11. Tracking allocations require ‘objspace' Thread.new do GC.start ObjectSpace.trace_object_allocations_start sleep 60 GC.start ObjectSpace.each_object do |o| next unless o.class == Array file = ObjectSpace.allocation_sourcefile(o) line = ObjectSpace.allocation_sourceline(o) puts "#{file}:#{line}" end end
12. $ bundle exec rbtrace -p 29217 -e 'Thread.new{ GC.start; ObjectSpace.trace_object_allocations_start; sleep 60; GC.start; ObjectSpace.each_object{|o| puts "#{ObjectSpace.allocation_sourcefile(o)}:#{ObjectSpace.all ocation_sourceline(o)}" if o.class == Array }}' > leak.log $ sort leak.log | uniq -c 106 GEMS_ROOT/gems/redis-namespace-1.5.1/lib/redis/namespace.rb:289 120 GEMS_ROOT/gems/redis-3.2.0/lib/redis/connection/ruby.rb:52 144 GEMS_ROOT/gems/redis-3.2.0/lib/redis/pipeline.rb:95 180 GEMS_ROOT/gems/redis-3.2.0/lib/redis/connection/command_helper.rb:19 509 GEMS_ROOT/gems/analytics-ruby-2.0.13/lib/segment/analytics/client.rb:348 525 GEMS_ROOT/gems/newrelic_rpm-3.13.2.302/lib/new_relic/agent/transaction_state.rb:37 526 GEMS_ROOT/gems/newrelic_rpm-3.13.2.302/lib/new_relic/agent/traced_method_stack.rb:23 1377 GEMS_ROOT/gems/analytics-ruby-2.0.13/lib/segment/analytics/worker.rb:29
13. Finding suspicious 23 def initialize(queue, write_key, options = {}) 24 symbolize_keys! options 25 @queue = queue 26 @write_key = write_key 27 @batch_size = options[:batch_size] || Queue::BATCH_SIZE 28 @on_error = options[:on_error] || Proc.new { |status, error| } 29 @batch = [] 30 @lock = Mutex.new 31 end
14. Dumping the heap require 'objspace' GC.start file = File.open('heap.json','w') ObjectSpace.dump_all(output: file) {"address":"0x7fae9590c1d0", "type":"ARRAY", "length":0, "memsize":40, "flags": {"wb_protected":true, "old":true, "long_lived":true, "marked":true}}
15. How a fix looks like
16. Simple example 1 require 'rbtrace' 2 3 $stdout.sync = true 4 $stderr.sync = true 5 6 puts $$ 7 8 class Worker 9 def initialize 10 @leak = 'wadus' 11 end 12 13 def create_worker 14 Thread.new do 15 puts Thread.current.object_id 16 loop do 17 sleep 60 18 end 19 end 20 end 21 end 22 23 loop do 24 Worker.new.create_worker 25 sleep 1 26 end
17. Finding the leak $ sort leak.log | uniq -c 31645 : 30 :0 15511 eval:1 14 leak.rb:10
18. Analysing snippets require 'segment' GC.start 100_000.times do Segment::Analytics.new({write_key: 'KEY'}) end GC.start objs = Hash.new(0) ObjectSpace.each_object do |o| objs[o.class] += 1 end puts(objs.sort_by { |_,v| -v }.first(10))
19. Objects in heap Proc 200389 RubyVM::Env 200324 Mutex 200009 String 146403 Array 120428 Hash 102510 Thread::Queue 100000 Segment::Analytics::Worker 100000 Segment::Analytics::Client 100000 Gem::Requirement 5543
20. Measuring allocations require 'peertransfer/segment' require 'allocation_tracer' PeertransferSegment.configure do |config| config.write_key = 'YOUR_WRITE_KEY' end ObjectSpace::AllocationTracer.trace do 50_000.times do |i| event = { user_id: 123, traits: { email: 'example@email.com' } PeertransferSegment.identify(event) end end p allocated: ObjectSpace::AllocationTracer.allocated_count_table p freed: ObjectSpace::AllocationTracer.freed_count_table
21. Allocated vs freed {:allocated=>{:T_NONE=>0, :T_OBJECT=>42, :T_CLASS=>0, :T_MO DULE=>0, :T_FLOAT=>0, :T_STRING=>1307744, :T_REGEXP=>0, : T_ARRAY=>651051, :T_HASH=>350051, :T_STRUCT=>1, :T_BIGNU M=>0, :T_FILE=>3, :T_DATA=>50087, :T_MATCH=>14, :T_COMPLEX =>0, :T_RATIONAL=>0, :unknown=>0, :T_NIL=>0, :T_TRUE=>0, :T_F ALSE=>0, :T_SYMBOL=>0, :T_FIXNUM=>0, :T_UNDEF=>0, :T_NOD E=>200045, :T_ICLASS=>0, :T_ZOMBIE=>0}} {:freed=>{:T_NONE=>0, :T_OBJECT=>4504, :T_CLASS=>0, :T_MOD ULE=>0, :T_FLOAT=>0, :T_STRING=>1228426, :T_REGEXP=>7, :T_ ARRAY=>630727, :T_HASH=>292873, :T_STRUCT=>904, :T_BIGNU M=>0, :T_FILE=>40, :T_DATA=>48635, :T_MATCH=>268, :T_COMPL EX=>0, :T_RATIONAL=>0, :unknown=>0, :T_NIL=>0, :T_TRUE=>0, : T_FALSE=>0, :T_SYMBOL=>0, :T_FIXNUM=>0, :T_UNDEF=>0, :T_N ODE=>213922, :T_ICLASS=>0, :T_ZOMBIE=>0}}
22. Simpler example require 'allocation_tracer' ObjectSpace::AllocationTracer.trace do 50_000.times do |i| a = i.to_s end end p allocated: ObjectSpace::AllocationTracer.allocated_count_table p freed: ObjectSpace::AllocationTracer.freed_count_table
23. Allocations vs freed {:allocated=>{:T_NONE=>0, :T_OBJECT=>0, :T_CLASS=>0, :T_MOD ULE=>0, :T_FLOAT=>0, :T_STRING=>50000, :T_REGEXP=>0, :T_AR RAY=>0, :T_HASH=>0, :T_STRUCT=>0, :T_BIGNUM=>0, :T_FILE=> 0, :T_DATA=>0, :T_MATCH=>0, :T_COMPLEX=>0, :T_RATIONAL=>0 , :unknown=>0, :T_NIL=>0, :T_TRUE=>0, :T_FALSE=>0, :T_SYMBOL =>0, :T_FIXNUM=>0, :T_UNDEF=>0, :T_NODE=>0, :T_ICLASS=>0, : T_ZOMBIE=>0}} {:freed=>{:T_NONE=>0, :T_OBJECT=>4072, :T_CLASS=>0, :T_MOD ULE=>0, :T_FLOAT=>0, :T_STRING=>7784, :T_REGEXP=>0, :T_AR RAY=>22762, :T_HASH=>1033, :T_STRUCT=>2419, :T_BIGNUM=>0 , :T_FILE=>2, :T_DATA=>1812, :T_MATCH=>10, :T_COMPLEX=>0, :T _RATIONAL=>0, :unknown=>0, :T_NIL=>0, :T_TRUE=>0, :T_FALSE= >0, :T_SYMBOL=>0, :T_FIXNUM=>0, :T_UNDEF=>0, :T_NODE=>10 255, :T_ICLASS=>0, :T_ZOMBIE=>0}}
24. Extra ball: Using GDB $ gdb -p PID gdb> p rb_eval_string("GC.start") gdb> p rb_eval_string("$all_objs = Hash.new(0)”) gdb> p rb_eval_string("ObjectSpace.each_object {|o| $all_objs[o.class] += 1}") gdb> p rb_eval_string("$stderr.puts($all_objs.inspect)") gdb> p rb_eval_string("GC.start") gdb> p rb_eval_string("$string_objs = Hash.new(0)”) gdb> p rb_eval_string("ObjectSpace.each_object(String) {|o| $string_objs[o] += 1}") gdb> p rb_eval_string("$stderr.puts($string_objs.inspect)") gdb> p rb_eval_string("$stderr.puts($string_objs.size)") gdb> p rb_eval_string("$max = 0") gdb> p rb_eval_string("$max_key = ''") gdb> p rb_eval_string("$string_objs.each { |k,v| $max_key = k if v > $max }")
25. {Module=>504, Array=>34775, String=>428082, Hash=>24444, RubyVM::InstructionSequence=>11903, Regexp=>988, Class=>1341, Range=>179, Gem::Version=>251, Gem::Requirement=>237, Bundler::Dependency=>40, MIME::Type=>1533, Proc=>787, RubyVM::Env=>581, Gem::Dependency=>141, Bundler::Index=>7, Bundler::SpecSet=>3, Rational=>1, Float=>315, Gem::Specification=>31, MatchData=>4, DependencyDetection::Dependent=>28, Time=>43, Pathname=>14, DaemonKit::Configuration=>1, Bundler::RubygemsIntegration::Modern=>1, Mutex=>40, Encoding=>99, Complex=>1, ThreadGroup=>1, IOError=>1, Binding=>1, Thread=>1, RubyVM=>1, NoMemoryError=>1, SystemStackError=>1, Bignum=>4, Random=>1, ARGF.class=>1, IO=>3, Data=>1, Object=>6, fatal=>1, Bundler::Source::Git::GitProxy=>2, Gem::Platform=>7, URI::Parser=>1, UnboundMethod=>2, Bundler::LazySpecification=>41, Bundler::Settings=>1, URI::HTTP=>1, Bundler::Source::Rubygems=>1, Bundler::Source::Path=>2, Bundler::Source::Git=>2, Bundler::Runtime=>1, Bundler::Definition=>1, OpenSSL::X509::Store=>1, BigDecimal=>2, Peertransfer::Settings::Values=>4, NewRelic::Control::ProxyServer=>1, OptionParser::CompletingHash=>1, OptionParser::Switch::NoArgument=>4, OptionParser::OptionMap=>6, OptionParser::List=>3, DaemonKit::AMQP=>1, Method=>6, ActiveSupport::Inflector::Inflections=>1, YAML::EngineManager=>1, I18n::Config=>1, JSON::Ext::Generator::State=>3, ActiveSupport::Notifications::Fanout=>1, Psych::Handler::DumperOptions=>1, NewRelic::MetricSpec=>67, NewRelic::Agent::StartupLogger=>1, NewRelic::Control::Frameworks::Ruby=>1, NewRelic::LocalEnvironment=>1, AMQP::Session=>7, EventMachine::DefaultDeferrable=>27, MultiJson::Adapters::JsonGem=>1, Databasedotcom::Client=>1, JsonSchema=>111, JsonMessage::Field=>111, Rake::TaskArguments=>1, NewRelic::Agent::Commands::AgentCommandRouter=>1, NewRelic::Agent::Commands::ThreadProfiler=>1, NewRelic::Agent::SqlSampler=>1, AMQP::AuthMechanismAdapter::Plain=>7, <Class:0x00000008a09800>=>1}
26. $ gdb -p PID gdb> p rb_eval_string("GC.start") gdb> p rb_eval_string("$string_objs = Hash.new 0") gdb> p rb_eval_string("ObjectSpace.each_object(String) {|o| $string_objs[o] += 1}") gdb> p rb_eval_string("$stderr.puts($string_objs.sort_by { |_,v| -v }.first(10))”) label 108443 defaultValue 106919 active 62427 value 62356 validFor 60974 deprecatedAndHidden 59451 relationshipName 59305 name 47864 updateable 46099 createable 46099
27. DEMO • In Debian jessie run ( or PIE-capable gdb version ): $ ruby -e 'puts $$; loop { sleep 1 }' • Run in another terminal: $ gdb -p (gdb) p rb_eval_string("puts $$") $1 = 8
28. Annex • http://ruby-doc.org/stdlib-2.1.0/libdoc/objspace/rdoc/ ObjectSpace.html • https://github.com/ko1/allocation_tracer • http://tmm1.net/ruby21-objspace/ • https://github.com/tmm1/rbtrace • https://github.com/srawlins/allocation_stats • https://github.com/SamSaffron/memory_profiler • https://samsaffron.com/archive/2015/03/31/debugging-memory- leaks-in-ruby • http://www.be9.io/2015/09/21/memory-leak/