These are chat archives for ManageIQ/manageiq/performance

8th
Oct 2015
Jason Frey
@Fryguy
Oct 08 2015 14:14 UTC
@matthewd Do you know if cycles in the ruby memory graph are normal (and the GC can handle them)?
I would assume so...I mean you can put a ref to yourself in a Hash
Joe Rafaniello
@jrafanie
Oct 08 2015 15:34 UTC
@matthewd @tenderlove any luck looking at the memory issues? By the way, I have the heap dump in Aaron's Not Very Good MRI Heap Analyzer
@Fryguy I got screenshot of what we were traversing earlier, I think
Screen Shot 2015-10-08 at 11.34.01 AM.png
Joe Rafaniello
@jrafanie
Oct 08 2015 15:47 UTC
The circular references make it hard to navigate, not sure what ultimately is keeping a reference to this chain after our ems refresh goes out of scope
going to try a run on an upstream appliance to verify i get the same information in objects retained in ObjectSpace
Matthew Draper
@matthewd
Oct 08 2015 16:42 UTC
Yes, cycles are normal
That graph ultimately roots at e, which is still in scope after the refresh, if your script looks like mine did
Matthew Draper
@matthewd
Oct 08 2015 16:53 UTC
We also saw some confusing stuff where the original manager was rooted, so it wasn't GCed even after it went out of scope
But most of that graph went away when I did a e.clear_association_cache, so I could focus on what was really being left behind
Jason Frey
@Fryguy
Oct 08 2015 17:02 UTC
we tried with e removed and there are still references
something in AR...either association_cache or the default_attributes, ends up holding references to VimString objects
Matthew Draper
@matthewd
Oct 08 2015 17:03 UTC
That's not surprising
But the AR object itself should be going away
Jason Frey
@Fryguy
Oct 08 2015 17:03 UTC
yeah
Matthew Draper
@matthewd
Oct 08 2015 17:05 UTC
Trying a thing.
Jason Frey
@Fryguy
Oct 08 2015 17:08 UTC
we narrowed down to default_attributes.dup, so I suspect that since we are getting a duped Hash, AR is mutating something deep and keeping references around
well, that's one place we narrowed down to
Joe Rafaniello
@jrafanie
Oct 08 2015 17:09 UTC
yes, @matthewd that graph is with e = nil; GC.start prior to the dump
FYI, @matthewd, here's the process memory info including the before and after e=nil; GC.start
             memory_usage |   total_allocated_objects |       total_freed_objects
                213639168 |                   7142252 |                   6235254 |                 before_refresh
                217980928 |                   7253815 |                   6346656 |       before_get_vc_data_total
                595841024 |                  19808295 |                  17598015 |          before_refresh_target
                733057024 |                  51845094 |                  47184042 |        before_post_refresh_ems
                845742080 |                  54423191 |                  50032450 | before_clearing_local_variable
                759767040 |                  54423244 |                  52710303 |  after_clearing_local_variable
Matthew Draper
@matthewd
Oct 08 2015 17:12 UTC
@jrafanie I realised the thing we actually want to compare is ObjectSpace.memsize_of_all
Specifically, it gets interesting when memory_usage diverges (upwards) from that, while processing the "main" response
(that is, in unmarshal_response via virtualMachines_locked)
.. though there does seem to be a similar up-and-away trend during save inventory ¯\_(ツ)_/¯
Jason Frey
@Fryguy
Oct 08 2015 17:33 UTC
@matthewd I have a nice visualiztion of the memory locally
You want to tmate in?
and I have it in pry, so I can query the object graph
also @dmetzger57
Matthew Draper
@matthewd
Oct 08 2015 17:47 UTC
@Fryguy sure… PM me a thing?
Jason Frey
@Fryguy
Oct 08 2015 17:53 UTC
unfortunately I can't tmate an already running process :(
I need to exit and reparse
Matthew Draper
@matthewd
Oct 08 2015 18:28 UTC
def iter n
  if n > 0
    1.times{
      iter(n-1)
    }
  else
    # null code
  end
end

def gc
  iter(100)
  GC.start
  GC.start
end
"Definitely GC"
n = Hash.new(0); ObjectSpace.each_object(ActiveRecord::Base) {|o| n[o.class.name] += 1 }; Hash[n.sort]
Joe Rafaniello
@jrafanie
Oct 08 2015 20:37 UTC
{"AuthUseridPassword"=>1,
 "Condition"=>3,
 "Disk"=>1000,
 "EmsCluster"=>60,
 "EmsFolder"=>4,
 "GuestDevice"=>1250,
 "HABTM_Storages"=>1150,
 "Hardware"=>1050,
 "Lan"=>100,
 "ManageIQ::Providers::Vmware::InfraManager"=>1051,
 "ManageIQ::Providers::Vmware::InfraManager::HostEsx"=>50,
 "ManageIQ::Providers::Vmware::InfraManager::Vm"=>1000,
 "MiqAction"=>3,
 "MiqEnterprise"=>1,
 "MiqEventDefinition"=>3,
 "MiqScsiLun"=>100,
 "MiqScsiTarget"=>100,
 "MiqServer"=>1,
 "OperatingSystem"=>1050,
 "ResourcePool"=>60,
 "Storage"=>1150,
 "Switch"=>50,
 "SystemService"=>100}
Joe Rafaniello
@jrafanie
Oct 08 2015 20:42 UTC
^ For reference, that's the retained AR::Base objects after a refresh
Jason Frey
@Fryguy
Oct 08 2015 20:48 UTC
For reference, @matthewd made a commit to Rails master and 4-2-stable rails/rails@1b6fcae
to fix rails/rails#21921
Joe Rafaniello
@jrafanie
Oct 08 2015 20:51 UTC
def dump_heap
  require "objspace"
  ObjectSpace.trace_object_allocations_start

  e = ExtManagementSystem.first
  e.verify_credentials

  EmsRefresh.refresh(e)
  e = nil
  GC.start
  ObjectSpace.trace_object_allocations_stop

  io=File.open("/tmp/my_dump2", "w")
  ObjectSpace.dump_all(output: io)
  io.close
end
Before
Ruby: 2.2.3
             memory_usage |   total_allocated_objects |       total_freed_objects
                211193856 |                   7164805 |                   6327875 |                 before_refresh
                836509696 |                  54445741 |                  50387192 | before_clearing_local_variable
                763670528 |                  54445809 |                  52732250 |  after_clearing_local_variable
{"AuthUseridPassword"=>1, "Condition"=>3, "Disk"=>1000, "EmsCluster"=>60, "EmsFolder"=>4, "GuestDevice"=>1250, "HABTM_Storages"=>1150, "Hardware"=>1050, "Lan"=>100, "ManageIQ::Providers::Vmware::InfraManager"=>1051, "ManageIQ::Providers::Vmware::InfraManager::HostEsx"=>50, "ManageIQ::Providers::Vmware::InfraManager::Vm"=>1000, "MiqAction"=>3, "MiqEnterprise"=>1, "MiqEventDefinition"=>3, "MiqScsiLun"=>100, "MiqScsiTarget"=>100, "MiqServer"=>1, "OperatingSystem"=>1050, "ResourcePool"=>60, "Storage"=>1150, "Switch"=>50, "SystemService"=>100}
106.183896 seconds
after
Ruby: 2.2.3
             memory_usage |   total_allocated_objects |       total_freed_objects
                214433792 |                   7163972 |                   6252732 |                 before_refresh
                841936896 |                  54448240 |                  50157653 | before_clearing_local_variable
                761929728 |                  54448308 |                  53745789 |  after_clearing_local_variable
{"Condition"=>3, "MiqAction"=>3, "MiqEnterprise"=>1, "MiqEventDefinition"=>3, "MiqServer"=>1}
102.400957 seconds
Joe Rafaniello
@jrafanie
Oct 08 2015 21:18 UTC
:cry:
Ruby: 2.2.3
             memory_usage |   total_allocated_objects |       total_freed_objects
               1108361216 |                  54448507 |                  52012730 | before_clearing_local_variable
               1098862592 |                  54448575 |                  53746073 |  after_clearing_local_variable
m:  53,152,272 | c:  45,008 | RubyVM::InstructionSequence     :
m:  26,940,896 | c: 453,224 | String     :
m:   7,128,352 | c:  27,096 | Hash     :
m:   6,887,832 | c:  87,299 | Array     :
m:   5,084,280 | c:   4,047 | Class     :
m:   3,778,320 | c:   6,470 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activemodel/lib/active_model/attribute_methods.rb:383
m:   3,139,193 | c:   5,042 | Regexp     :
m:   2,750,376 | c:   1,576 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/dependencies.rb:457
m:   2,690,177 | c:  48,820 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230
m:   2,181,680 | c:  16,454 | RubyVM::Env     :
m:   2,058,832 | c:   1,562 | Module     :
m:   1,759,992 | c:  16,923 | Proc     :
m:   1,352,567 | c:  24,236 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   1,291,504 | c:   4,530 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/hash/keys.rb:142
m:   1,050,432 | c:       1 | Thread     :
m:   1,035,888 | c:   3,816 | MIME::Types::Container     :
m:     898,304 | c:     319 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/gems/memoist-0.11.0/lib/memoist.rb:166
m:     839,431 | c:  15,043 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1214
m:     644,849 | c:  15,029 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/psych-2.0.15/lib/psych.rb:376
m:     608,600 | c:  15,215 | ActionDispatch::Journey::Nodes::Cat     :
m:     593,168 | c:     786 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/attribute_methods.rb:48
m:     517,592 | c:   2,231 | Sexp     :
m:     472,832 | c:     196 | ActiveRecord::AttributeMethods::GeneratedAttributeMethods     :
m:     436,464 | c:     394 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/dependencies.rb:274
m:     417,384 | c:   7,499 | String     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/attribute_methods.rb:359
m:     350,920 | c:   1,907 | MIME::Type     :
m:     317,856 | c:   1,806 | Mutex     :
m:     296,458 | c:   5,463 | String     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/inflector/methods.rb:251
m:     282,512 | c:   2,207 | ActionDispatch::Journey::Route     :
m:     267,096 | c:   2,154 | RubyVM::Env     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/class/attribute.rb:86
m:     262,320 | c:   6,558 | ActionDispatch::Journey::Format     :
m:     260,320 | c:   6,508 | ActionDispatch::Journey::Nodes::Slash     :
m:     247,192 | c:   2,207 | ActionDispatch::Journey::Path::Pattern     :
m:     238,152 | c:       3 | FastGettext::GetText::MOFile     :
m:     220,107 | c:   4,045 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1222
m:     213,137 | c:   3,907 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2050
m:     207,200 | c:   1,400 | RubyVM::Env     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/class/attribute.rb:78
m:     202,113 | c:   3,651 | String     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/inflector/methods.rb:259
m:     201,280 | c:      44 | ActiveRecord::AttributeMethods::GeneratedAttr
Joe Rafaniello
@jrafanie
Oct 08 2015 21:49 UTC
here's the object space counts, memory after using the iter/gc thing
m:  52,065,872 | c:  43,496 | RubyVM::InstructionSequence     :
m:  34,516,324 | c: 635,798 | String     :
m:   7,216,232 | c:  27,707 | Hash     :
m:   6,813,576 | c:  85,509 | Array     :
m:   5,054,960 | c:   4,026 | Class     :
m:   4,398,528 | c:   7,532 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activemodel/lib/active_model/attribute_methods.rb:383
m:   3,132,444 | c:   5,034 | Regexp     :
m:   2,750,376 | c:   1,576 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/dependencies.rb:457
m:   2,262,072 | c:  17,043 | RubyVM::Env     :
m:   2,055,408 | c:   1,558 | Module     :
m:   1,822,496 | c:  17,524 | Proc     :
m:   1,291,504 | c:   4,530 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/hash/keys.rb:142
m:   1,050,432 | c:       1 | Thread     :
m:   1,035,888 | c:   3,816 | MIME::Types::Container     :
m:     898,304 | c:     319 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/gems/memoist-0.11.0/lib/memoist.rb:166
m:     667,880 | c:     885 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/attribute_methods.rb:48
m:     640,118 | c:  14,951 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/psych-2.0.15/lib/psych.rb:376
m:     608,600 | c:  15,215 | ActionDispatch::Journey::Nodes::Cat     :
m:     517,592 | c:   2,231 | Sexp     :
m:     475,392 | c:     421 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/dependencies.rb:274
m:     472,832 | c:     196 | ActiveRecord::AttributeMethods::GeneratedAttributeMethods     :
m:     350,920 | c:   1,907 | MIME::Type     :
m:     317,680 | c:   1,805 | Mutex     :
m:     282,512 | c:   2,207 | ActionDispatch::Journey::Route     :
m:     267,344 | c:   2,156 | RubyVM::Env     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/class/attribute.rb:86
m:     262,320 | c:   6,558 | ActionDispatch::Journey::Format     :
m:     260,320 | c:   6,508 | ActionDispatch::Journey::Nodes::Slash     :
m:     247,192 | c:   2,207 | ActionDispatch::Journey::Path::Pattern     :
m:     238,152 | c:       3 | FastGettext::GetText::MOFile     :
m:     207,200 | c:   1,400 | RubyVM::Env     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/core_ext/class/attribute.rb:78
m:     201,280 | c:      44 | ActiveRecord::AttributeMethods::GeneratedAttributeMethods     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/attribute_methods.rb:70
m:     178,112 | c:     253 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/associations/builder/association.rb:113
m:     174,480 | c:   4,362 | ActionDispatch::Journey::Nodes::Symbol     :
m:     174,480 | c:   4,362 | ActionDispatch::Journey::Format::Parameter     :
m:     174,064 | c:     253 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/associations/builder/association.rb:121
m:     174,040 | c:   4,351 | ActionDispatch::Journey::Nodes::Group     :
m:     173,920 | c:   4,348 | ActionDispatch::Journey::Nodes::Literal     :
m:     167,379 | c:   3,159 | String     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activesupport/lib/active_support/dependencies.rb:457
m:     165,984 | c:     228 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/bundler/gems/rails-599c31cf7d61/activerecord/lib/active_record/associations/builder/singular_association.rb:16
m:     160,984 | c:     623 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/psych-2.0.15/lib/psych/visitors/to_ruby.rb:161
m:     139,840 | c:   1,748 | Gem::Dependency     :
m:     139,524 | c:   2,781 | String     /Users/joerafaniello/.gem
Jason Frey
@Fryguy
Oct 08 2015 21:50 UTC
No VimService?
Joe Rafaniello
@jrafanie
Oct 08 2015 21:52 UTC
I don't see VimService at all
:+1:
Joe Rafaniello
@jrafanie
Oct 08 2015 22:08 UTC
So, did memory test again... took screenshots
4.2.4...
Screen Shot 2015-10-08 at 6.02.04 PM.png
4-2-stable
Screen Shot 2015-10-08 at 6.06.35 PM.png
It seems better :confused: