I've been battling what appears to be a memory leak in my Rails application for some time now. I think I've tracked part of the problem to a certain class, but I am seeing confusing results from memory-profiler.
Short background - the AuditMessage class constructs user-friendly strings based on the data in an audit log record (from the audited gem). This message is constructed when the audit record is created so it is run very often. My first test was to benchmark-memory to confirm that auditing and message generation was the problem:
Full audit with AuditMessage: 91 M memsize, 8.7 M retained
Without AuditMessage: 59 M memsize, 4.5 M retained
Without auditing at all: 33.8 M memsize; 2.9 M retained
That tells me that the auditing and AuditMessage are problematic. I created a short test file based on this debugging article. Essentially, I'm generating 100 messages, running Garbage Collection, checking memory, and repeating.
ENV['RAILS_ENV'] = 'production'
require 'objspace'
require 'memory_profiler'
require File.expand_path("../config/environment", __FILE__)
def rss
`ps -eo pid,rss | grep #{Process.pid} | awk '{print $2}'`.to_i
end
AuditMessage.new(AuditEntry.first).text_message
GC.start
puts "rss: #{rss} live objects #{GC.stat[:heap_live_slots]}"
MemoryProfiler.start
AuditEntry.limit(1000).in_groups_of(100) do |entries|
entries.each do |a|
AuditMessage.new(a).text_message
end
GC.start
puts "rss: #{rss} live objects #{GC.stat[:heap_live_slots]}, total allocated: #{GC.stat[:total_allocated_objects]}"
end
puts "FINAL: rss: #{rss} live objects #{GC.stat[:heap_live_slots]}, total allocated: #{GC.stat[:total_allocated_objects]}"
report = MemoryProfiler.stop
report.pretty_print
I believe the GC.stat results confirm this is a memory leak because the heap_live_slots continue to increase. Please correct me if I'm wrong:
rss: 181688 live objects 572803
rss: 273484 live objects 631408, total allocated: 5307067
rss: 275464 live objects 654608, total allocated: 5743585
rss: 275468 live objects 677286, total allocated: 6180094
rss: 275468 live objects 698909, total allocated: 6618187
rss: 275476 live objects 722677, total allocated: 7066883
rss: 275476 live objects 745892, total allocated: 7509013
rss: 278512 live objects 771616, total allocated: 7955413
rss: 278992 live objects 794085, total allocated: 8368117
rss: 278992 live objects 815336, total allocated: 8763087
rss: 314976 live objects 852800, total allocated: 9319171
FINAL: rss: 315884 live objects 852790, total allocated: 9319200
I expected that the results from MemoryProfiler would show string leaks from my AuditMessage class. However, the results point towards database_statments and other activerecord internals. For example, the largest retained string objects are from activerecord:
Retained String Report
-----------------------------------
886 "User"
886 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:111
782 "Activity"
778 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:111
1 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activemodel-5.0.0.1/lib/active_model/naming.rb:148
1 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.0.0.1/lib/active_support/inflector/methods.rb:124
1 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-5.0.0.1/lib/active_support/inflector/methods.rb:69
1 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/concurrent-ruby-1.0.5/lib/concurrent/collection/map/non_concurrent_map_backend.rb:24
By location also points to ActiveRecord and ActiveModel:
retained memory by location
-----------------------------------
1128000 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-5.0.0.1/lib/active_record/result.rb:117
943634 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:111
45718 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activemodel-5.0.0.1/lib/active_model/attribute_methods.rb:383
20072 /Users/jackcollins/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/schema_statements.rb:238
And finally:
retained memory by gem
-----------------------------------
2286378 activerecord-5.0.0.1
54151 activesupport-5.0.0.1
51342 activemodel-5.0.0.1
How should I interpret this data? Has anyone else run into a similar issue with string memory leaks in Ruby/Rails?