Posted By

kulmala on 03/06/14


Tagged

memory profiler


Versions (?)

MemTool for Ruby 2.0 & Rails 4.0


 / Published in: Rails
 

URL: http://www.happybootstrapper.com/2014/profile-leaky-sidekiq-job-heroku

A little tool for debugging memory problems in Heroku. Works also in Mac. Instructions and further in info at http://www.happybootstrapper.com/2014/profile-leaky-sidekiq-job-heroku

  1. # http://www.happybootstrapper.com/2014/profile-leaky-sidekiq-job-heroku
  2. # Uses Ruby-Prof in dev env, add the following to gemfile development section:
  3. # gem 'ruby-prof'
  4.  
  5. module MemTool
  6.  
  7. def self.start(file_name = 'no_name')
  8. unless Rails.env.test?
  9. begin
  10. start_profiling(file_name)
  11. rescue => e
  12. Rails.logger.warn(sprintf 'MemTool: %s', e.message)
  13. end
  14. end
  15. end
  16.  
  17. def self.stop
  18. unless Rails.env.test?
  19. begin
  20. stop_profiling
  21. rescue => e
  22. Rails.logger.warn(sprintf 'MemTool: %s', e.message)
  23. end
  24. end
  25. end
  26.  
  27. def self.object_stats
  28. stats = Hash.new(0)
  29. ObjectSpace.each_object { |o| stats[o.class] += 1 }
  30. stats
  31. end
  32.  
  33. def self.get_memory_usage
  34. `ps -o rss= -p #{Process.pid}`.to_i
  35. end
  36.  
  37. private
  38.  
  39. def self.to_sorted_array(hsh)
  40. hsh.sort { |a, b| b[1] <=>a[1] }.collect { |k, v| "#{k}: #{v}" }
  41. end
  42.  
  43. def self.start_profiling(file_name)
  44. @file_name = file_name
  45. @object_stats = object_stats
  46. @memory_stats = {memory_usage: get_memory_usage}
  47. @gc_stats = GC.stat
  48. RubyProf.start unless Rails.env.production?
  49. end
  50.  
  51. def self.stop_profiling
  52. result = RubyProf.stop unless Rails.env.production?
  53. new_gc_stats = GC.stat
  54. new_memory_stats = {memory_usage: get_memory_usage}
  55. new_object_stats = object_stats
  56.  
  57. if Rails.env.production?
  58. log_other_stats(new_gc_stats, new_object_stats, new_memory_stats)
  59. else
  60. time = DateTime.now.to_i
  61. print_ruby_prof_stats(result, time)
  62. print_other_stats(new_gc_stats, new_object_stats, new_memory_stats, time)
  63. end
  64.  
  65. clean_up
  66. end
  67.  
  68. def self.clean_up
  69. @file_name = nil
  70. @gc_stats = nil
  71. @object_stats = nil
  72. @memory_stats = nil
  73. end
  74.  
  75. def self.print_ruby_prof_stats(result, time)
  76. html_file = open_file_for_writing time, 'html'
  77. printer = RubyProf::GraphHtmlPrinter.new(result)
  78. printer.print(html_file, :min_percent => 5)
  79. html_file.close
  80. end
  81.  
  82.  
  83. def self.log_other_stats(new_gc_stats, new_object_stats, new_memory_stats)
  84. # The sleeps help the log lines to get into right order
  85. Rails.logger.info 'Memory Profile for ' << @file_name
  86. Rails.logger.info "**** MEMORY ****"
  87. sleep(1.0/20.0)
  88. log_stats new_memory_stats, @memory_stats
  89. sleep(1.0/20.0)
  90. Rails.logger.info "**** GARBAGE COLLECTOR ****"
  91. sleep(1.0/20.0)
  92. log_stats new_gc_stats, @gc_stats
  93. sleep(1.0/20.0)
  94.  
  95. Rails.logger.info "**** OBJECTS IN MEMORY ****"
  96. sleep(1.0/20.0)
  97. log_stats new_object_stats, @object_stats
  98.  
  99. end
  100.  
  101. def self.print_other_stats(new_gc_stats, new_object_stats, new_memory_stats, time)
  102. text_file = open_file_for_writing time, 'txt'
  103.  
  104. text_file.puts "**** MEMORY ****"
  105. print_stats new_memory_stats, @memory_stats, text_file
  106. text_file.puts "\n"
  107.  
  108. text_file.puts "**** GARBAGE COLLECTOR ****"
  109. print_stats new_gc_stats, @gc_stats, text_file
  110.  
  111. text_file.puts "\n"
  112.  
  113. text_file.puts "**** OBJECTS IN MEMORY ****"
  114. print_stats new_object_stats, @object_stats, text_file
  115.  
  116. text_file.close
  117. end
  118.  
  119.  
  120. def self.open_file_for_writing(time, suffix)
  121. File.new "#{Rails.root}/log/#{time}_#{@file_name}.#{suffix}", 'a+'
  122. end
  123.  
  124. def self.print_stats(stats, last_stats, out)
  125. title = sprintf("%10s | %10s |", 'Before', 'Delta')
  126. out.puts title
  127.  
  128. line_format = "%10d | %10d | %-30s"
  129. stats.sort { |(k1, v1), (k2, v2)| v2 <=> v1 }.each do |key, value|
  130. delta = 0
  131. if last_stats[key]
  132. delta = value - last_stats[key]
  133. end
  134. log_entry = sprintf(line_format, value, delta, key)
  135. out.puts log_entry
  136. end
  137. end
  138.  
  139. def self.log_stats(stats, last_stats)
  140. title = sprintf("%10s | %10s |", 'Before', 'Delta')
  141. Rails.logger.info title
  142.  
  143. # filter away classes with less than 10 instances
  144. stats.reject! { |key, value| value < 10 }
  145.  
  146. line_format = "%10d | %10d | %-30s"
  147. stats.sort { |(k1, v1), (k2, v2)| v2 <=> v1 }.each do |key, value|
  148. delta = 0
  149. if last_stats[key]
  150. delta = value - last_stats[key]
  151. end
  152. log_entry = sprintf(line_format, value, delta, key)
  153. Rails.logger.info log_entry
  154. end
  155. end
  156. end

Report this snippet  

You need to login to post a comment.