These are chat archives for ManageIQ/manageiq/performance

8th
Oct 2015
Jason Frey
@Fryguy
Oct 08 2015 14:14
@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
@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
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
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
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
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
That's not surprising
But the AR object itself should be going away
Jason Frey
@Fryguy
Oct 08 2015 17:03
yeah
Matthew Draper
@matthewd
Oct 08 2015 17:05
Trying a thing.
Jason Frey
@Fryguy
Oct 08 2015 17:08
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
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
@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
@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
@Fryguy sure… PM me a thing?
Jason Frey
@Fryguy
Oct 08 2015 17:53
unfortunately I can't tmate an already running process :(
I need to exit and reparse
Matthew Draper
@matthewd
Oct 08 2015 18:28
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
{"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
^ For reference, that's the retained AR::Base objects after a refresh
Jason Frey
@Fryguy
Oct 08 2015 20:48
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
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
: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
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
No VimService?
Joe Rafaniello
@jrafanie
Oct 08 2015 21:52
I don't see VimService at all
:+1:
Joe Rafaniello
@jrafanie
Oct 08 2015 22:08
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: