Stāstiņš par Ruby problēmām ar atmiņu

Published in

Mitigate

4 min readNov 17, 2015

Warning: You build has exceeded the memory limit of 4G on 1 container. The results of this build are likely invalid. We have taken a snapshot of the memory usage at the time, which you can find in a build artifact named memory-usage.txt. The RSS column in this file shows the amount of memory used by each process, measured in kilobytes.

Šādu paziņojumu es saņēmu no Circle CI, kad biju laimīgi pabeidzis izstrādāt nelielus labojumus rails applikācijā.

Pirmais kas iešāvās prātā, protams, ka tas ir kāds no tiem memory leakiem. Tad nu nedaudz pagūglējot protams var atrast visādas problēmas, kā citi ir 2 nedēļas meklējuši leakus utt.

http://www.be9.io/2015/09/21/memory-leak/

http://samsaffron.com/archive/2015/03/31/debugging-memory-leaks-in-ruby

Šajos piemēros gan problēmas ir bijušas ar HTTP pieprasījumiem, manā gadījumā tas ir RSpec testos, bet ideja līdzīga.

Mēģinājums #1: Drukāt atmiņu

Tad nu sāku rakstīt veidu kā logot atmiņu pēc katra RSpec testa.

RSpec.configure do |c|
  c.around do |example|
    example.run
    sampler = NewRelic::Agent::Samplers::MemorySampler.new.sampler
    usage = sampler.get_sample
    Rails.logger.debug "Memory usage: #{usage.round} @ #{example.location}"
  end
end

Spriežot pēc rezultātiem ir skaidrs ka atmiņa sāk strauji augt kautkur pēc tieši manis veiktajām izmaiņām ar resource_planner.

cat log/test.log | grep 'Memory usage:'
...
Memory usage: 483 @ ./spec/features/resource_planner/allocation_spec.rb:706
Memory usage: 483 @ ./spec/features/resource_planner/allocation_spec.rb:739
Memory usage: 483 @ ./spec/features/resource_planner/allocation_spec.rb:763
Memory usage: 484 @ ./spec/features/resource_planner/dashboard_spec.rb:12
Memory usage: 486 @ ./spec/features/resource_planner/plan_spec.rb:26
Memory usage: 498 @ ./spec/features/resource_planner/plan_spec.rb:35
Memory usage: 505 @ ./spec/features/resource_planner/plan_spec.rb:63
Memory usage: 513 @ ./spec/features/resource_planner/plan_spec.rb:74
Memory usage: 525 @ ./spec/features/resource_planner/plan_spec.rb:91
Memory usage: 536 @ ./spec/features/resource_planner/plan_spec.rb:129
...
Memory usage: 1861 @ ./spec/features/workflow/versions_spec.rb:73

Hmm, liekas aizdomīgi ka atmiņa ļoti strauji kāpj uz augšu pēc allocation_spec.rb.

Mēģinājums #2: Drukāt objektus

Varētu paskatīties kas pa objektiem ir atmiņā, aizdoma ir ka tie varētu būt maniresouce_planner objekti. Tad nu pēc katra testa varētu atfiltrēt skaitu ar objektiem kas mantoti no ActiveRecord::Base.

RSpec.configure do |c|
  c.around do |example|
    GC.start
    ...
    klasses = ActiveRecord::Base.descendants
    klasses.each do |klass|
      count = ObjectSpace.each_object(klass) { |x| x }
      if count > 0
        puts "--- #{klass}: #{count}"
      end
    end
  end
end

Rezultātā pēc katra testa tiek izprintēti objekti ar skaitu.

Memory: 260 @ ./spec/features/resource_planner/allocation_spec.rb:636
--- ResourcePlanner::Plan: 8
--- ResourcePlanner::Allocation: 4
--- ResourcePlanner::Assignment: 4
--- ResourcePlanner::PlanTemplate: 3
--- ResourcePlanner::Resource: 13
--- ResourcePlanner::Task: 9
--- ResourcePlanner::ProjectPlan: 8
...
Memory: 260 @ ./spec/features/resource_planner/allocation_spec.rb:674
--- ResourcePlanner::Plan: 15
--- ResourcePlanner::Allocation: 7
--- ResourcePlanner::Assignment: 7
--- ResourcePlanner::PlanTemplate: 6
--- ResourcePlanner::Resource: 22
--- ResourcePlanner::Task: 17
--- ResourcePlanner::ProjectPlan: 15
...

Pētot dažus piemērus atklāju, ka GC.start tomēr visu kārtīgi neiztīra, tapēc GC.start jālaiž vairākas reizes.

while new_count = decreased_count(new_count)
  GC.start
end

Mēģinājums #3: Atrast references

Tālāk mēģinu atrast kā var apskatīties konkrētā objekta referneces uz citiem objektiem. Pagūglējot atrodu tādu ruby-mass, bet kauktas līdz galam nestrādā, met visādu exceptionus, eh, nav laika baigi pētīt un cerība ir diezgan maza ka kautko sapratīšu no tām visām refernecēm.

Mēģinājums #4: GC

Ko nu vel varētu izprintēt, varbūt GC kautko vel labu zin? Rokoties pa internetu un lasot par GC uzdūros uz Heroku rakstu Incremental Garbage Collection in Ruby 2.2, kurā tiek sīki izstāstīts kā strādā Ruby GC, Major GC, Minor GC, GC.stat. Varētu paskatīties cik reizes tad tas GC te laižas, jo aizdoma ka kādi no GC ENV mainīgajiem varbūt jāpietūnē.

RSpec.configure do |c|
  c.around do |example|
    GC.start
    ...
    stats = GC.stat
    major = stats[:major_gc_count]
    minor = stats[:minor_gc_count]
    puts "GC major: #{major}, minor: #{minor}"
  end
end

Rezultātā notiek kautkas ļoti neparedzēts, izrādās ka GC vienkārši pārstāj strādāt.

Memory: 268 @ ./spec/features/resource_planner/allocation_spec.rb:597
GC major: 54, minor: 12
Memory: 260 @ ./spec/features/resource_planner/allocation_spec.rb:636
GC major: 57, minor: 12
Memory: 260 @ ./spec/features/resource_planner/allocation_spec.rb:674
GC major: 57, minor: 12
Memory: 254 @ ./spec/features/resource_planner/allocation_spec.rb:710
GC major: 57, minor: 12

Kapēc lai GC pārstātu strādāt? Ruby bugs?

Pētot log failus atklājas, ka testā viens no AJAX requestiem atgriež 500 Internal Server Error, jo dzēšot objektus esmu nonācis bezgalīgā ciklā un rezultātā SystemStackError: stack level too deep.

Tā kā šis ir JS tests, tad lai phantomjs varētu pieslēgties pie servera, tam ir nepieicešam reāls HTTP ports, tapēc Capybara piestartē atsevišķā Threadā rails applikāciju. Tad nu doma ir nosimulēt situāciju kad threadā tiek uztaisīts bezgalīgs cikls, rezultātā saprotu ka Ruby tomēr kautkas nav labi.

class Infinity
  def self.run
    1.times { run }
  end
endThread.new do
  loop do
    begin
      Infinity.run
    rescue Exception => e
      puts e.message
    end
    sleep 3
  end
endThread.new do
  loop do
    "A" * 1000
  end
end7.times do
  GC.start
  puts "GC major: #{GC.stat[:major_gc_count]}, minor: #{GC.stat[:minor_gc_count]}"
  sleep 1
end

Rezultāts ir bēdīgs, process pakarās un vienīgais veids kā apturēt ir kill -9.

ruby 2.3.0dev (2015–11–17 trunk 52623) [x86_64-darwin15]

ruby gc_threads_issue.rb
stack level too deep
GC major: 0, minor: 0
GC major: 0, minor: 0
GC major: 0, minor: 0
Killed: 9

ruby 2.2.3p173 (2015–08–18 revision 51636) [x86_64-darwin14]

stack level too deep
GC major: 1, minor: 0
GC major: 1, minor: 0
GC major: 1, minor: 0
Killed: 9

ruby 2.1.5p273 (2014–11–13 revision 48405) [x86_64-darwin14.0]

stack level too deep
GC major: 1, minor: 2
GC major: 14, minor: 14
GC major: 24, minor: 23
Killed: 9

Tad nu vajadzētu pieteikt problēmu Ruby. Pameklēju “gc + stack” redmainā un izrādās ka ir jau atvērts bugs Ruby Issue #11692 ar līdzīgu problēmu, tad nu pieliku savus komentārus, redzēs kas būs tālāk.

Secinājumi

Atmiņas problēmas nav viegli risināt un prasa mega daudz laiku risināšanā.

Vajadzētu pielikt, lai testos, ja AJAX pieprasījumi atgriež 500to, tad tests nofailo.

Ja Capybara taisītu jaunu procesu nevis taisīt threadus, tad šāda problēma nebūtu. PR Capybarai?

Neizmantot threadus, ruby vienkārši tam joprojām nav gatavs. Atceramies timeout problēmas?