These are chat archives for ManageIQ/manageiq/performance

7th
Oct 2015
Alex Krzos
@akrzos
Oct 07 2015 01:51 UTC
So if I followed this correctly, The "tiny" environment displayed nearly similar memory usage on Ruby 2.0 vs 2.2.3 ~184MiB in Growth over on RSS, When you moved to the medium environment, we can see an actual difference in amount of memory required when bumping to ruby 2.2.3. Also your recorded timings for 2.0.0, 2.2.3 compared to CFME 5.4 (Ruby 2.0) and 5.5.0.1 values I have are better than mine. We might be able to chalk that up to hardware as the cpu I'm running virtualized on is Sandy Bridge as your likely running locally on a mac with haswell I guess.
Jason Frey
@Fryguy
Oct 07 2015 12:44 UTC
@kbrock what do you mean by changing to json? Or rather where?
Keenan Brock
@kbrock
Oct 07 2015 12:57 UTC
@Fryguy yea - no idea if vmware speaks json. would be nice to figure out what they speak. and if soap it is, wonder if there is a c extension (like yaml and json have) that can help us cut down this parsing... nokogiri?
lol: roll your own soap - but probably more practical: savon
interesting the number of people who want to do nokogiri and soap another example
Jason Frey
@Fryguy
Oct 07 2015 13:43 UTC
I don't know if the new versions have added json... They have been soap forever
I believe we already parse with nokogiri and handsoap
@roliveri Can give more details if needed
Keenan Brock
@kbrock
Oct 07 2015 13:48 UTC
I'm pretty sure we re-invented a parser, with our own vim types
but didn't dive too deep. I'll ping rich
Alex Krzos
@akrzos
Oct 07 2015 13:50 UTC
So I ran with export RUBY_GC_HEAP_OLDOBJECT_LIMIT_FACTOR=0.9 on vmware-medium environment and the impact of that + GC.start(before/after) benchmark shows a decrease of ~70MiB however the "used" RSS is still not close to 5.4 levels
also the timing value is higher due to all GC as major
so with that data I'd say there is some level of impact with the generational GC
Dennis Metzger
@dmetzger57
Oct 07 2015 14:14 UTC
@akrzos thought you were on PTO starting today?
Keenan Brock
@kbrock
Oct 07 2015 14:18 UTC
the plane will wait...
Alex Krzos
@akrzos
Oct 07 2015 14:33 UTC
@dmetzger57 tomorrow I'm on PTO
akrzos @akrzos checks his calendar
Alex Krzos
@akrzos
Oct 07 2015 14:33 UTC
you had me think it was thursday for a second
Dennis Metzger
@dmetzger57
Oct 07 2015 14:37 UTC
😀
Alex Krzos
@akrzos
Oct 07 2015 14:39 UTC
vmware-large with export + GC.start(before/after):
2015-10-07 10:01:28,285 [I] Running command `export RUBY_GC_HEAP_OLDOBJECT_LIMIT_FACTOR=0.9; cd /var/www/miq/vmdb; echo "ActiveRecord::Base.logger.level = 1;mrss_start = MiqProcess.processInfo()[:memory_usage];vmem_start = MiqProcess.processInfo[:memory_size];gc_start = GC.stat;e = ExtManagementSystem.find_by_name('vmware-large');GC.start;timing = Benchmark.realtime {EmsRefresh.refresh e};GC.start;mrss_end = MiqProcess.processInfo()[:memory_usage];vmem_end = MiqProcess.processInfo[:memory_size];gc_end = GC.stat;mrss_change = mrss_end - mrss_start;vmem_change = vmem_end - vmem_start;puts \"#{mrss_start}, #{mrss_end}, #{mrss_change}\";puts \"#{vmem_start}, #{vmem_end}, #{vmem_change}\";puts \"#{gc_start}\";puts \"#{gc_end}\";puts Process.pid;timing" | bundle exec bin/rails c 2> /dev/null` (utils/ssh.py:130)
2015-10-07 10:37:56,280 [D] pbench stop-tools skipped due to ['pbench']['disable'] set to true. (utils/perf.py:406)
2015-10-07 10:37:56,286 [I] Iteration: 0, Timing: 2175.90035641, Process: 16514 (utils/perf.py:314)
2015-10-07 10:37:56,289 [I] RSS Memory start: 174440448, end: 990314496, change: 815874048 (utils/perf.py:316)
2015-10-07 10:37:56,291 [I] Virt Memory start: 476307456, end: 1368248320, change: 891940864 (utils/perf.py:318)
2015-10-07 10:37:56,293 [I] GC stat start: {:count=>64, :heap_allocated_pages=>2132, :heap_sorted_length=>2226, :heap_allocatable_pages=>0, :heap_available_slots=>869039, :heap_live_slots=>747753, :heap_free_slots=>121286, :heap_final_slots=>0, :heap_marked_slots=>75984, :heap_swept_slots=>299252, :heap_eden_pages=>2132, :heap_tomb_pages=>0, :total_allocated_pages=>2648, :total_freed_pages=>516, :total_allocated_objects=>6944659, :total_freed_objects=>6196906, :malloc_increase_bytes=>371216, :malloc_increase_bytes_limit=>16777216, :minor_gc_count=>1, :major_gc_count=>63, :remembered_wb_unprotected_objects=>846, :remembered_wb_unprotected_objects_limit=>19514, :old_objects=>74409, :old_objects_limit=>475927, :oldmalloc_increase_bytes=>371664, :oldmalloc_increase_bytes_limit=>16777216} (utils/perf.py:319)
2015-10-07 10:37:56,296 [I] GC stat end: {:count=>1444, :heap_allocated_pages=>11972, :heap_sorted_length=>22405, :heap_allocatable_pages=>8798, :heap_available_slots=>4879821, :heap_live_slots=>3443087, :heap_free_slots=>1436734, :heap_final_slots=>0, :heap_marked_slots=>3440265, :heap_swept_slots=>5028327, :heap_eden_pages=>11969, :heap_tomb_pages=>3, :total_allocated_pages=>15586, :total_freed_pages=>3614, :total_allocated_objects=>213339677, :total_freed_objects=>209896590, :malloc_increase_bytes=>85840, :malloc_increase_bytes_limit=>16777216, :minor_gc_count=>1, :major_gc_count=>1443, :remembered_wb_unprotected_objects=>38998, :remembered_wb_unprotected_objects_limit=>35098, :old_objects=>3373979, :old_objects_limit=>3036581, :oldmalloc_increase_bytes=>86288, :oldmalloc_increase_bytes_limit=>16777216} (utils/perf.py:320)
2015-10-07 10:37:56,298 [I] RSS Mem Total(Console + Benchmark) Used: 944.4375 MiB (utils/perf.py:322)
2015-10-07 10:37:56,300 [I] RSS Mem Change(Benchmark) Used: 778.078125 MiB (utils/perf.py:323)
2015-10-07 10:37:56,302 [I] Virt Mem Total(Console + Benchmark) Used: 1304.86328125 MiB (utils/perf.py:325)
2015-10-07 10:37:56,305 [I] Virt Mem Change(Benchmark) Used: 850.62109375 MiB (utils/perf.py:326)
ugh 36minutes for refresh
so much less memory usage
RSS Change was 1248MiB in previous benchmarks
timing was ~462s (no export RUBY_GC_HEAP_OLDOBJECT_LIMIT_FACTOR) vs 2175s
5.4 timing was only 719s
5.4 RSS change memory usage was at 607MiB
Alex Krzos
@akrzos
Oct 07 2015 14:44 UTC
so much closer to 5.4 with vmware-large
but timing is terriable
Also note I have introduced: "ActiveRecord::Base.logger.level = 1" into benchmark as well, since I use console
that prevents logging all of the queries to stdout
we could use that information in the future however would need something to parse or analyze it
Also benchmark is slightly faster according to my vmware-small results by setting the logger
not sure how much faster with larger environments
Joe Rafaniello
@jrafanie
Oct 07 2015 15:19 UTC
@akrzos can you try something? put this in /etc/default/evm at the bottom, restart your shell, ssh in, etc., then run your benchmark?
export RUBY_GC_HEAP_GROWTH_FACTOR=1.1
export RUBY_GC_MALLOC_LIMIT=4000100
export RUBY_GC_MALLOC_LIMIT_MAX=16000100
export RUBY_GC_MALLOC_LIMIT_GROWTH_FACTOR=1.1
export RUBY_GC_OLDMALLOC_LIMIT_MAX=16000100
i'm seeing my osx setup that starts at ~200 MB and grows to ~800 MB with a 95 second refresh instead start at just under 200 MB and grow to 615 MB with a 92 second refresh
untuned:
2.2.3 213942272 2759380992
2.2.3 833331200 3938070528
94.996781 seconds
above knobs tuned:
2.2.3 198332416 2743435264
2.2.3 607002624 3206205440
93.109235 seconds
Considering the wall time didn't increase and we saved memory, we could probably tweak it more to get MOAR memory
@Fryguy would you expect the bulk of allocations from VimService.rb, VimHash, VimArray, VimString, etc. to occur towards the beginning, middle, or end of the ems refresh?
Matthew Draper
@matthewd
Oct 07 2015 15:29 UTC
@jrafanie are you looking for a good time to do a dump?
Joe Rafaniello
@jrafanie
Oct 07 2015 15:29 UTC
Because everytime I run the refresh here, the memory jumps from 500+ MB to 700/800 MB over a span of the last 5-10 seconds of the refresh
(that's with untuned ruby 2.2.3)
Jason Frey
@Fryguy
Oct 07 2015 15:30 UTC
For Vmware we ask for all the data up front, so, at the beginning
Joe Rafaniello
@jrafanie
Oct 07 2015 15:30 UTC
So, that's what I thought... and why I'm :confused:
Jason Frey
@Fryguy
Oct 07 2015 15:30 UTC
but of course we have to hold on to it for the life of the parser, so I don't expect GC to remove it until at least after the parsing
which means it probably survives some GC attempts
Alex Krzos
@akrzos
Oct 07 2015 15:31 UTC
@jrafanie I'll try again with those, should I try on the large or medium provider?
Matthew Draper
@matthewd
Oct 07 2015 15:31 UTC
How's that compare to the parse/store split?
Joe Rafaniello
@jrafanie
Oct 07 2015 15:31 UTC
yeah, @Fryguy, just curious why it's jumping in memory by hundreds of MB in the last few seconds of the refresh
Jason Frey
@Fryguy
Oct 07 2015 15:31 UTC
technically, once the parse is done, the references should be released...but there might be some cache_with_timeout stuff in there
Joe Rafaniello
@jrafanie
Oct 07 2015 15:32 UTC
that would indicate there's a lot of new allocations happening
Alex Krzos
@akrzos
Oct 07 2015 15:32 UTC
silly me though set my benchmark to run twice and the second attempt against large still hasn't finished, this is longer than 36minutes now so I suspect something wrong
Jason Frey
@Fryguy
Oct 07 2015 15:32 UTC
you can probably throw a GC.start in the refresher between the parse and store to see if it releases the memory
Joe Rafaniello
@jrafanie
Oct 07 2015 15:32 UTC
but anyway...
@akrzos I did the medium provider
do whatever you have good "before" numbers for
Jason Frey
@Fryguy
Oct 07 2015 15:32 UTC

last few seconds of the refresh

That's database

Alex Krzos
@akrzos
Oct 07 2015 15:33 UTC
@jrafanie gotcha
Jason Frey
@Fryguy
Oct 07 2015 15:33 UTC
Can you start your allocations check right between the parse/store split?
@jrafanie Are you using ObjectSpace.dump_all for allocations or something else like allocation_tracer?
Joe Rafaniello
@jrafanie
Oct 07 2015 15:34 UTC
Yeah, I'll do the untuned version
I'll do allocation_tracer as long as it doesn't segfault
Are we interested in all allocations or retained objects?
Matthew Draper
@matthewd
Oct 07 2015 15:34 UTC
Do we currently intend to ship a custom GC config?
Joe Rafaniello
@jrafanie
Oct 07 2015 15:35 UTC
@matthewd I don't know, it's a possibility
I did it since it was easy to play with
@Fryguy I swear I used to know where the parse/store split was in the refresher code... not anymore... where should I start the allocation tracking?
Matthew Draper
@matthewd
Oct 07 2015 15:40 UTC
app/models/ems_refresh/refreshers/ems_refresher_mixin.rbparse_inventory vs save_inventory
Joe Rafaniello
@jrafanie
Oct 07 2015 15:42 UTC
Ah, @matthewd, there it is, thanks!
Joe Rafaniello
@jrafanie
Oct 07 2015 15:49 UTC
@matthewd do you see an issue with custom GC env variables?
Jason Frey
@Fryguy
Oct 07 2015 15:49 UTC

Are we interested in all allocations or retained objects?

Not sure...whichever one points us to the line of code to fix ;)

As far as custom GC vars go, I'm ok with having something OOTB...maybe you can try the same variables in the travis config
Matthew Draper
@matthewd
Oct 07 2015 15:50 UTC
Only as a general concern that we have, overall, a moderately diverse set of operations going on, so I'm nervous about second-guessing the core team's default tuning
Jason Frey
@Fryguy
Oct 07 2015 15:50 UTC
That presumes the core team has a default tuning
Matthew Draper
@matthewd
Oct 07 2015 15:51 UTC
To presume otherwise would be to assume either they're actively rejecting data-supported patches to change the values, or that we're the first people to ever think of measuring what's going on
Without actually researching to disprove either of the above.. neither of them sound hugely likely
Jason Frey
@Fryguy
Oct 07 2015 15:52 UTC
Wait, I'm a little lost...who did you mean by "core team"
Matthew Draper
@matthewd
Oct 07 2015 15:52 UTC
MRI
Jason Frey
@Fryguy
Oct 07 2015 15:52 UTC
ohhhh
I thought you meant our core team
So, MRI's tuning is based on short-lived scripts, right?
I thought it's kind of a known thing that every long running Rails app should do some kind of tuning on their own
Matthew Draper
@matthewd
Oct 07 2015 15:55 UTC
I'm not sure… the bursty nature of refresh workers seems more likely to down the short-lived script end of the spectrum anyway, in some senses
Unless "tuned for short-lived scripts" is code for "don't really bother collecting; we'll die soon anyway", but I don't think that's the case
The weird thing about our behaviour is, I believe, going to be the fact we construct tons of objects, retaining references to all of them just long enough to make them "old"… and then suddenly lose interest in them all at once
OTOH, that's not really something we can avoid, so I guess we're more interested in the objects that are supposed to die along the way
Jason Frey
@Fryguy
Oct 07 2015 16:09 UTC
yeah
does it make sense to force full GCs in the parser/store split anyway?
because we know that is a clear demarcation point
and we know that parser creates a ton of objects and store will too when it queries the database
@jrafanie Might be useful to have numbers right at that split...both for the pre and post split
Joe Rafaniello
@jrafanie
Oct 07 2015 16:13 UTC
So, @Fryguy I'm doing all allocations first, around 3 areas, get_and_filter_vc_data, refresh_target, and post_refresh_ems
Joe Rafaniello
@jrafanie
Oct 07 2015 16:30 UTC
Correction, I'm doing the memory data before each of these 3 steps, then I'll do the allocations
2.2.3 201523200 2727923712 Before EmsRefresh.refresh
2.2.3 206864384 2733166592 Before get_vc_data_total
2.2.3 592019456 3160674304 Before refresh_target
2.2.3 725757952 3324502016 Before post_refresh_ems
2.2.3 833851392 3878154240 After EmsRefresh.refresh
Joe Rafaniello
@jrafanie
Oct 07 2015 16:37 UTC
FYI, timings hash for that same run:
{:get_ems_data=>0.3343837261199951,
 :get_vc_data=>19.349103927612305,
 :get_vc_data_ems_customization_specs=>0.03280520439147949,
 :filter_vc_data=>0.0002720355987548828,
 :get_vc_data_host_scsi=>3.6980948448181152,
 :get_vc_data_total=>23.454447984695435,
 :parse_vc_data=>0.9565079212188721,
 :db_save_inventory=>56.88113594055176,
 :post_refresh_ems=>4.460295915603638,
 :total_time=>85.79023313522339}
So, get_vc_data_total consumes almost 400 MB, refresh_target ~130 MB, post_refresh_ems ~100 MB
Matthew Draper
@matthewd
Oct 07 2015 16:42 UTC
I guess we need some GC stats too, to really put those in perspective
Because "increases total process allocation by" is potentially quite different from "consumes"
.. which in turn could influence the degree to which each one actually contributes to the peak usage
It's clearly not actually going to be true, but get_vc_data_total "could" be freeing almost all of that 400MB, and then refresh_target consuming 500+MB (in which case we'd need to look at the latter first), or it could be retaining almost all of it, in which case a change in refresh_target is going to have limited potential
I think that makes sense… maybe?
Joe Rafaniello
@jrafanie
Oct 07 2015 16:46 UTC
doh, typo'd get_vc_data_total is actually, get_and_filter_vc_data... they describe the same thing though
here's all allocations for that part
All get_and_filter_vc_data allocations
2335464    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2361    T_STRING    String
1719840    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2361    T_STRING    VimString
450850    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1192    T_STRING    String
365319    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2383    T_STRING    String
345241    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2383    T_ARRAY    Array
292114    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230    T_STRING    String
225419    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1190    T_STRING    String
225405    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1196    T_DATA    Nokogiri::XML::NodeSet
211350    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1221    T_STRING    String
211347    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1219    T_STRING    String
184957    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1194    T_STRING    String
175944    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197    T_STRING    VimString
172990    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2366    T_STRING    String
163151    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197    T_STRING    String
137177    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2245    T_STRING    String
137154    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2243    T_ARRAY    Array
103135    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimTypes.rb:43    T_STRING    String
86227    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2239    T_STRING    String
76676    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2359    T_STRING    String
76634    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2361    T_ARRAY    Array
76619    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2361    T_MATCH    MatchData
76450    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2357    T_ARRAY    Array
76435    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/MiqVimInventory.rb:2361    T_NODE
67711    /Users/joerafaniello/.gem/ruby/2.2.3/gems/nokogiri-1.6.6.2/lib/nokogiri/xml/node_set.rb:187    T_DATA    Nokogiri::XML::Element
62251    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1199    T_STRING    String
61384    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1203    T_NODE
59273    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1228    T_STRING    String
56917    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1216    T_DATA    Nokogiri::XML::NodeSet
56911    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1216    T_DATA    RubyVM::Env
56907    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1216    T_DATA    Proc
56158    /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1196    T_DATA    Nokogiri::XML::Text
@matthewd what GC stats do you want? GC.stat or something specific?
Matthew Draper
@matthewd
Oct 07 2015 16:48 UTC
@jrafanie I'm not sure which it is :sweat_smile:
Joe Rafaniello
@jrafanie
Oct 07 2015 16:49 UTC
this is GC.stat example, do you want this before each phase of the refresh?
Matthew Draper
@matthewd
Oct 07 2015 16:49 UTC
But we want some sort of measure of "memory ruby thinks it's actively using"… is that the live object count?
Joe Rafaniello
@jrafanie
Oct 07 2015 16:49 UTC
{:count=>26,
 :heap_allocated_pages=>236,
 :heap_sorted_length=>237,
 :heap_allocatable_pages=>0,
 :heap_available_slots=>96193,
 :heap_live_slots=>95955,
 :heap_free_slots=>238,
 :heap_final_slots=>0,
 :heap_marked_slots=>58135,
 :heap_swept_slots=>28803,
 :heap_eden_pages=>236,
 :heap_tomb_pages=>0,
 :total_allocated_pages=>236,
 :total_freed_pages=>0,
 :total_allocated_objects=>654884,
 :total_freed_objects=>558929,
 :malloc_increase_bytes=>122256,
 :malloc_increase_bytes_limit=>16777216,
 :minor_gc_count=>22,
 :major_gc_count=>4,
 :remembered_wb_unprotected_objects=>648,
 :remembered_wb_unprotected_objects_limit=>760,
 :old_objects=>57452,
 :old_objects_limit=>70352,
 :oldmalloc_increase_bytes=>2253744,
 :oldmalloc_increase_bytes_limit=>16777216}
Matthew Draper
@matthewd
Oct 07 2015 16:50 UTC
total_allocated_objects - total_freed_objects sounds plausible, I think?
Joe Rafaniello
@jrafanie
Oct 07 2015 16:50 UTC
yup
I'll do both
Matthew Draper
@matthewd
Oct 07 2015 16:50 UTC
I guess that's heap_live_slots ¯\_(ツ)_/¯
Joe Rafaniello
@jrafanie
Oct 07 2015 16:51 UTC
slots aren't objects though
Matthew Draper
@matthewd
Oct 07 2015 16:52 UTC
I'm not sure we care about the distinction
See how I implied I know what the distinction is, there? ;)
Matthew Draper
@matthewd
Oct 07 2015 17:10 UTC
@jrafanie let's pretend I have no idea what's going on for a moment…
That allocation list you pasted… is that all allocations, or allocations that are being retained?
Joe Rafaniello
@jrafanie
Oct 07 2015 17:10 UTC
Shouldn't be too hard :laughing:
Matthew Draper
@matthewd
Oct 07 2015 17:10 UTC
Hopefully the former?
Joe Rafaniello
@jrafanie
Oct 07 2015 17:10 UTC
that was ALL
line 2361 looks suspicious, not sure how big the objects are that it's duplicating on the split
Matthew Draper
@matthewd
Oct 07 2015 17:12 UTC
diff --git a/gems/pending/VMwareWebService/MiqVimInventory.rb b/gems/pending/VMwareWebService/MiqVimInventory.rb
index 86e4376..7d21c34 100644
--- a/gems/pending/VMwareWebService/MiqVimInventory.rb
+++ b/gems/pending/VMwareWebService/MiqVimInventory.rb
@@ -2354,28 +2354,7 @@ def hashTarget(baseHash, keyString, create = false)
   # Array keys (between "[" and "]") can contain ".", so we can't just use split.
   #
   def splitPropPath(propPath)
-    pathArray = []
-    inKey = false
-    pc = ''
-
-    propPath.split(//).each do |c|
-      case c
-      when '.'
-        unless inKey
-          pathArray << pc
-          pc = ''
-          next
-        end
-      when '['
-        inKey = true
-      when ']'
-        inKey = false
-      end
-      pc << c
-    end
-    pathArray << pc unless pc.empty?
-
-    pathArray
+    propPath.scan(/(?:[^\[\].]|\[[^\]]*\])+/)
   end
   private :splitPropPath
Wanna try that?
Joe Rafaniello
@jrafanie
Oct 07 2015 17:12 UTC
but we assumed you don't know what you're doing ;-)
sure, I'll try it in a second
Matthew Draper
@matthewd
Oct 07 2015 17:14 UTC
I wonder whether there are tests that (indirectly) exercise that method, and prove it still does what it's supposed to
However, while this might save a few temporary allocations, they should be getting GC swept quite happily — I wouldn't expect them to affect the numbers we really care about
Joe Rafaniello
@jrafanie
Oct 07 2015 17:16 UTC
@roliveri might have tests for it, maybe @Fryguy knows too
Matthew Draper
@matthewd
Oct 07 2015 17:17 UTC
Another easy win by freezing the '[' on the former 2383 (first line of tagAndKey)
Joe Rafaniello
@jrafanie
Oct 07 2015 17:20 UTC
yeah
ok, baseline
             memory_usage |   total_allocated_objects |       total_freed_objects
                215818240 |                   7141858 |                   6232783 |          Before before_refresh
                217022464 |                   7253421 |                   6344317 |  Before get_and_filter_vc_data
                608546816 |                  19807911 |                  17595879 |          Before refresh_target
                726130688 |                  51844717 |                  47177787 |        Before post_refresh_ems
                831467520 |                  54422815 |                  50023942 |           Before after_refresh
87.569556 seconds
Joe Rafaniello
@jrafanie
Oct 07 2015 17:25 UTC
with splitPropPath one liner:
             memory_usage |   total_allocated_objects |       total_freed_objects
                214974464 |                   7141742 |                   6235690 |          Before before_refresh
                215568384 |                   7253302 |                   6347871 |  Before get_and_filter_vc_data
                611176448 |                  14631697 |                  12536579 |          Before refresh_target
                740704256 |                  46668499 |                  41810066 |        Before post_refresh_ems
                851464192 |                  49246597 |                  45065894 |           Before after_refresh
85.229173 seconds
Matthew Draper
@matthewd
Oct 07 2015 17:27 UTC
Yeah, so, less allocations, but as expected, no actual effect
The next few top allocations seem to feature literals-we-should-freeze pretty heavily
But it sounds like we need to be looking at the retained object list instead
Joe Rafaniello
@jrafanie
Oct 07 2015 17:29 UTC
with '['.freeze on 2383 on top of the one liner
             memory_usage |   total_allocated_objects |       total_freed_objects
                218435584 |                   7141741 |                   6236360 |          Before before_refresh
                220733440 |                   7253304 |                   6347693 |  Before get_and_filter_vc_data
                575627264 |                  14168945 |                  12027147 |          Before refresh_target
                716480512 |                  46205751 |                  41434415 |        Before post_refresh_ems
                834543616 |                  48783849 |                  44182226 |           Before after_refresh
Alex Krzos
@akrzos
Oct 07 2015 17:35 UTC
FYI @jrafanie if you are using the console to refresh, are you still using the VIMBroker? There is a patch you need to make for the VIMBroker and another patch to get Host data
The patch for 5.4 and 5.5 is different for the Host data
Joe Rafaniello
@jrafanie
Oct 07 2015 17:36 UTC
No, I'm not using the broker with console
Alex Krzos
@akrzos
Oct 07 2015 17:36 UTC
also that increases memory usage
Joe Rafaniello
@jrafanie
Oct 07 2015 17:36 UTC
or runner
Alex Krzos
@akrzos
Oct 07 2015 17:36 UTC
gotcha, my benchmarks when run through the framework do the patching
let me get the patches I run
sed -i 's/def self.init_console(use_vim_broker = false)/def self.init_console(use_vim_broker = true)/g' /var/www/miq/vmdb/app/models/ems_refresh.rb
sed -i 's/@active_roles.include?("ems_inventory") ? :cache_scope_ems_refresh : :cache_scope_core/@active_roles.include?("ems_inventory") ? :cache_scope_ems_refresh : :cache_scope_ems_refresh/g' /var/www/miq/vmdb/app/models/miq_vim_broker_worker/runner.rb
of course you also have to have the ems_operations role enabled
Joe Rafaniello
@jrafanie
Oct 07 2015 17:38 UTC
ah, yes, i do the first
Alex Krzos
@akrzos
Oct 07 2015 17:38 UTC
and wait for the VIMBroker to be ready
Joe Rafaniello
@jrafanie
Oct 07 2015 17:38 UTC
no,sorry, I don't use the broker
Alex Krzos
@akrzos
Oct 07 2015 17:38 UTC
So might be better to use a brokerless provider (RHEVM)
Joe Rafaniello
@jrafanie
Oct 07 2015 17:40 UTC
I can try with a broker to see if it changes anythign
Alex Krzos
@akrzos
Oct 07 2015 17:41 UTC
so without doing the cache patch, my rss memory change was ~385MiB for medium and now it's 462MiB
Matthew Draper
@matthewd
Oct 07 2015 17:41 UTC
@akrzos what's "was" vs "now"? :confused:
Alex Krzos
@akrzos
Oct 07 2015 17:43 UTC

was == 5.5.0.3 benchmaked without

sed -i 's/@active_roles.include?("ems_inventory") ? :cache_scope_ems_refresh : :cache_scope_core/@active_roles.include?("ems_inventory") ? :cache_scope_ems_refresh : :cache_scope_ems_refresh/g' /var/www/miq/vmdb/app/models/miq_vim_broker_worker/runner.rb

now == 5.5.0.3 patched for cache_scope_ems_refresh

if I enable "ems_inventory" the refresh worker spawns and completes the job without my benchmark running, so I keep that disabled on my benchmarked appliance
Ok so I got results in for the tunings you suggested @jrafanie:
export RUBY_GC_HEAP_GROWTH_FACTOR=1.1
export RUBY_GC_MALLOC_LIMIT=4000100
export RUBY_GC_MALLOC_LIMIT_MAX=16000100
export RUBY_GC_MALLOC_LIMIT_GROWTH_FACTOR=1.1
export RUBY_GC_OLDMALLOC_LIMIT_MAX=16000100
Joe Rafaniello
@jrafanie
Oct 07 2015 17:48 UTC
ok, was about to ask :worried:
Alex Krzos
@akrzos
Oct 07 2015 17:48 UTC
I'm going to put them into a ethercalc spreadsheet so we can read them more easily
Joe Rafaniello
@jrafanie
Oct 07 2015 17:48 UTC
ok
I can add virt memory
and gc.stat before/after too
timings are poor
hmm
wondering why timings are that much poorer, perhaps VIMBroker, since my previous results were not patching the cache scope correctly
let me peak at the gc stat
Joe Rafaniello
@jrafanie
Oct 07 2015 17:58 UTC
@akrzos are you saying the timings are poor for both tuned and untuned or just one?
Jason Frey
@Fryguy
Oct 07 2015 17:58 UTC
I'm surprised you need to patch...that init_console thing was written to be called directly by just having the script call EmsRefresh.init_console(true) or something to that effect
Alex Krzos
@akrzos
Oct 07 2015 17:58 UTC
@jrafanie Yes let me run the test one more time
without patching cache
and see if timings drop dramatically
because this is entirely inconsistent with everything else, grrr, Let me try and figure out what changed here
Joe Rafaniello
@jrafanie
Oct 07 2015 18:04 UTC
@matthewd, ok, did a run that did "start allocation trace, yield to the refresh, GC.start, stop allocation trace, then walk all the objects in object space..."
WTF is the autosave_association cached value here at the top?
m: 106,980,163 | c: 560,279 | :
m:  12,360,518 | c:   8,129 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/autosave_association.rb:152
m:  10,421,095 | c:   7,153 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/transform_values.rb:9
m:  10,393,030 | c:   7,134 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_methods/dirty.rb:165
m:   7,042,115 | c:  46,558 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   7,022,886 | c:  97,467 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:9
m:   6,829,222 | c:  94,756 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:5
m:   6,088,196 | c: 151,819 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_set/builder.rb:79
m:   3,904,176 | c:   8,981 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/attribute_methods.rb:383
m:   3,760,076 | c:  48,627 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230
m:   3,277,903 | c:   7,173 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:84
m:   2,949,318 | c:   4,797 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:457
m:   2,642,464 | c:   2,258 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:116
m:   1,978,892 | c:   9,386 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:547
m:   1,954,650 | c:  37,971 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:168
m:   1,911,288 | c:  17,858 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations.rb:162
m:   1,876,232 | c:   6,501 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation.rb:34
m:   1,851,414 | c:   1,049 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:10
m:   1,823,055 | c:  39,972 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:35
m:   1,804,911 | c:   7,845 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation.rb:23
m:   1,735,666 | c:   9,387 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:554
m:   1,719,840 | c:  42,996 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:110
m:   1,645,782 | c:   7,126 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/dirty.rb:199
m:   1,599,878 | c:  38,752 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:17
m:   1,531,698 | c:  37,591 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:273
m:   1,425,873 | c:  34,828 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:12
m:   1,418,729 | c:   7,128 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/inheritance.rb:61
m:   1,291,504 | c:   4,530 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:142
m:   1,171,581 | c:  15,095 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1214
m:   1,157,904 | c:  13,158 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations/alias_tracker.rb:63
From what GC.start's documentation says, it should do a full GC, not just a minor GC, not sure what those are... it looks like we're retaining some VimService.rb objects for some reason... maybe it's not really GC'ing fully?
ok, stepping away for a bit, let me know if you think of anything
here's the same "retained objects after GC.start in ObjectSpace" sorted by count of objects by line number
m: 106,980,163 | c: 560,279 | :
m:   6,088,196 | c: 151,819 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_set/builder.rb:79
m:   7,022,886 | c:  97,467 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:9
m:   6,829,222 | c:  94,756 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:5
m:   3,760,076 | c:  48,627 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230
m:   7,042,115 | c:  46,558 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   1,719,840 | c:  42,996 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:110
m:   1,823,055 | c:  39,972 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:35
m:   1,599,878 | c:  38,752 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:17
m:   1,954,650 | c:  37,971 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:168
m:   1,531,698 | c:  37,591 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:273
m:   1,425,873 | c:  34,828 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:12
m:     797,482 | c:  19,310 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/table.rb:100
m:   1,911,288 | c:  17,858 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations.rb:162
m:     616,360 | c:  15,409 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/predications.rb:16
m:     655,243 | c:  15,146 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/psych-2.0.15/lib/psych.rb:376
m:   1,171,581 | c:  15,095 | /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1214
m:     617,561 | c:  14,830 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract_adapter.rb:269
m:     567,480 | c:  14,187 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations/association_scope.rb:15
m:     528,840 | c:  13,221 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/table.rb:18
m:   1,157,904 | c:  13,158 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations/alias_tracker.rb:63
m:     385,734 | c:   9,489 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:518
m:   1,735,666 | c:   9,387 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:554
m:   1,978,892 | c:   9,386 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:547
m:     377,289 | c:   9,386 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:546
m:     364,443 | c:   9,033 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_methods/dirty.rb:169
m:   3,904,176 | c:   8,981 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/attribute_methods.rb:383
m:     367,256 | c:   8,191 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/validations.rb:300
m:  12,360,518 | c:   8,129 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/autosave_association.rb:152
m:     326,636 | c:   8,129 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/errors.rb:73
m:     315,316 | c:   7,846 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation.rb:27
m:     689,928 | c:   7,845 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation/delegation.rb:106
m:   1,804,911 | c:   7,845 | /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/
Joe Rafaniello
@jrafanie
Oct 07 2015 18:09 UTC
m == memsize_of(object) for all objects on the line number
Alex Krzos
@akrzos
Oct 07 2015 18:09 UTC
@jrafanie running benchmarks, without patching cache scope, timing drops dramatically
Jason Frey
@Fryguy
Oct 07 2015 18:11 UTC
I think there's a little bit of cache_with_timeout in there
or maybe that's for C&U...I'll have to check
nope nevermind
It's possible VimService itself does some sort of caching
Matthew Draper
@matthewd
Oct 07 2015 18:15 UTC
@jrafanie can you throw the class name into that report please?
Joe Rafaniello
@jrafanie
Oct 07 2015 18:24 UTC
As you requested @matthewd, here's with class names although I messed up the formatting
m:  53,102,088 | c:  44,973 | RubyVM::InstructionSequence     :
m:  22,327,513 | c: 339,641 | String     :
m:  12,356,984 | c:   8,075 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/autosave_association.rb:152
m:  10,416,904 | c:   7,103 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/transform_values.rb:9
m:  10,388,272 | c:   7,078 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_methods/dirty.rb:165
m:   7,056,936 | c:  26,639 | Hash     :
m:   6,941,960 | c:  96,416 | ActiveRecord::Attribute::FromUser     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:9
m:   6,894,232 | c:  87,101 | Array     :
m:   6,724,368 | c:  93,394 | ActiveRecord::Attribute::FromDatabase     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:5
m:   6,069,748 | c: 151,601 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_set/builder.rb:79
m:   5,104,000 | c:  22,000 | VimString     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   5,076,664 | c:   4,045 | Class     :
m:   3,778,320 | c:   6,470 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/attribute_methods.rb:383
m:   3,619,497 | c:  50,091 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230
m:   3,270,424 | c:   7,075 | ActiveSupport::HashWithIndifferentAccess     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:84
m:   3,139,017 | c:   5,042 | Regexp     :
m:   2,750,376 | c:   1,576 | RubyVM::InstructionSequence     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:457
m:   2,642,464 | c:   2,258 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:116
m:   2,172,112 | c:  16,383 | RubyVM::Env     :
m:   2,056,216 | c:   1,559 | Module     :
m:   1,981,814 | c:  38,301 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:168
m:   1,974,816 | c:   9,336 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:547
m:   1,876,232 | c:   6,501 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation.rb:34
m:   1,848,000 | c:   1,000 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:10
m:   1,804,339 | c:  39,767 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:35
m:   1,801,568 | c:   7,796 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/relation.rb:23
m:   1,799,656 | c:  24,739 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   1,754,168 | c:  16,867 | Proc     :
m:   1,731,608 | c:   9,335 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:554
m:   1,719,840 | c:  42,996 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:110
m:   1,641,400 | c:   7,075 | ActiveSupport::HashWithIndifferentAccess     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/dirty.rb:199
m:   1,549,938 | c:  38,118 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:17
m:   1,476,640 | c:  36,916 | Array     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:273
m:   1,389,954 | c:  34,413 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:12
m:   1,291,504 | c:   4,530 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/
Matthew Draper
@matthewd
Oct 07 2015 18:25 UTC
:heart:
Joe Rafaniello
@jrafanie
Oct 07 2015 18:26 UTC
here's sorted by object counts
m:  22,327,513 | c: 339,641 | String     :
m:   6,069,748 | c: 151,601 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_set/builder.rb:79
m:   6,941,960 | c:  96,416 | ActiveRecord::Attribute::FromUser     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:9
m:   6,724,368 | c:  93,394 | ActiveRecord::Attribute::FromDatabase     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute.rb:5
m:   6,894,232 | c:  87,101 | Array     :
m:   3,619,497 | c:  50,091 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1230
m:  53,102,088 | c:  44,973 | RubyVM::InstructionSequence     :
m:   1,719,840 | c:  42,996 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/result.rb:110
m:   1,804,339 | c:  39,767 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:35
m:   1,981,814 | c:  38,301 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:168
m:   1,549,938 | c:  38,118 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/type/string.rb:17
m:   1,476,640 | c:  36,916 | Array     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/hash_with_indifferent_access.rb:273
m:   1,389,954 | c:  34,413 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activesupport-4.2.4/lib/active_support/core_ext/hash/keys.rb:12
m:   7,056,936 | c:  26,639 | Hash     :
m:   1,799,656 | c:  24,739 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:   5,104,000 | c:  22,000 | VimString     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1197
m:     744,400 | c:  18,610 | Arel::Attributes::Attribute     /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/table.rb:100
m:   1,754,168 | c:  16,867 | Proc     :
m:   2,172,112 | c:  16,383 | RubyVM::Env     :
m:     616,360 | c:  15,409 | Arel::Nodes::Equality     /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/predications.rb:16
m:   1,105,826 | c:  15,406 | String     /Users/joerafaniello/Code/manageiq/gems/pending/VMwareWebService/VimService.rb:1214
m:     608,600 | c:  15,215 | ActionDispatch::Journey::Nodes::Cat     :
m:     645,239 | c:  15,022 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/psych-2.0.15/lib/psych.rb:376
m:     568,360 | c:  14,209 | Arel::Nodes::BindParam     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract_adapter.rb:269
m:     567,520 | c:  14,188 | Array     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations/association_scope.rb:15
m:     528,840 | c:  13,221 | Array     /Users/joerafaniello/.gem/ruby/2.2.3/gems/arel-6.0.3/lib/arel/table.rb:18
m:   1,157,904 | c:  13,158 | Arel::Table     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/associations/alias_tracker.rb:63
m:     373,864 | c:   9,337 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:546
m:   1,974,816 | c:   9,336 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:547
m:   1,731,608 | c:   9,335 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:554
m:     373,320 | c:   9,333 | Array     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/core.rb:518
m:     361,107 | c:   8,970 | String     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/attribute_methods/dirty.rb:169
m:     323,000 | c:   8,075 | ActiveModel::Errors     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/validations.rb:300
m:     323,000 | c:   8,075 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activemodel-4.2.4/lib/active_model/errors.rb:73
m:  12,356,984 | c:   8,075 | Hash     /Users/joerafaniello/.gem/ruby/2.2.3/gems/activerecord-4.2.4/lib/active_record/autosave_association.rb:152
Note, this was the same "start allocation trace, yield to the refresh, GC.start, stop allocation trace, then walk all the objects in object space..."
@matthewd I expect a kangaroo for my birthday, :laughing:
Matthew Draper
@matthewd
Oct 07 2015 18:30 UTC
Some of these seem very odd that we'd be retaining them post-refresh :confused:
Joe Rafaniello
@jrafanie
Oct 07 2015 18:42 UTC
check my work, maybe i did something silly
def log_object_space
  require "objspace"
  ObjectSpace.trace_object_allocations_start

  yield
  GC.start

  ObjectSpace.trace_object_allocations_stop

  object_hash = {}
  ObjectSpace.each_object ...
end

  #setup stuff
log_object_space { EmsRefresh.refresh(e) }
Alex Krzos
@akrzos
Oct 07 2015 18:48 UTC
@jrafanie fixed the timings, on that sheet
I had the wrong csv copy and pasted in there at first
so not patching cache scope saves you about ~36s
adding memory now
Alex Krzos
@akrzos
Oct 07 2015 19:36 UTC
So just noticed this
on my 20minute graphs comparing 5.5 vs 5.4
for C&U
look at VIMBroker graph
You can see when I turn on C&U
5.5 rss grows, but 5.4 doesn't
Keenan Brock
@kbrock
Oct 07 2015 20:27 UTC
@akrzos stop finding issues man ;)
(aka thanks)
Alex Krzos
@akrzos
Oct 07 2015 20:28 UTC
@kbrock You guys are getting a week and half break :smirk:
Keenan Brock
@kbrock
Oct 07 2015 20:35 UTC
:)