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.
@kbrock what do you mean by changing to json? Or rather where?
@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
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
I'm pretty sure we re-invented a parser, with our own vim types
but didn't dive too deep. I'll ping rich
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
@akrzos thought you were on PTO starting today?
the plane will wait...
@dmetzger57 tomorrow I'm on PTO
akrzos @akrzos checks his calendar
you had me think it was thursday for a second
😀
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
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
@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
Note, I just cargo culted the values from here: http://collectiveidea.com/blog/archives/2015/02/19/optimizing-rails-for-memory-usage-part-2-tuning-the-gc/
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?
@jrafanie are you looking for a good time to do a dump?
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)
For Vmware we ask for all the data up front, so, at the beginning
So, that's what I thought... and why I'm :confused:
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
@jrafanie I'll try again with those, should I try on the large or medium provider?
How's that compare to the parse/store split?
yeah, @Fryguy, just curious why it's jumping in memory by hundreds of MB in the last few seconds of the refresh
technically, once the parse is done, the references should be released...but there might be some cache_with_timeout stuff in there
that would indicate there's a lot of new allocations happening
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
you can probably throw a GC.start in the refresher between the parse and store to see if it releases the memory
but anyway...
@akrzos I did the medium provider
do whatever you have good "before" numbers for
last few seconds of the refresh
That's database
@jrafanie gotcha
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?
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?
Do we currently intend to ship a custom GC config?
@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?
app/models/ems_refresh/refreshers/ems_refresher_mixin.rb… parse_inventory vs save_inventory
Ah, @matthewd, there it is, thanks!
@matthewd do you see an issue with custom GC env variables?
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
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
That presumes the core team has a default tuning
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
Wait, I'm a little lost...who did you mean by "core team"
MRI
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
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
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
So, @Fryguy I'm doing all allocations first, around 3 areas, get_and_filter_vc_data, refresh_target, and post_refresh_ems
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
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
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?
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?
@jrafanie I'm not sure which it is :sweat_smile:
this is GC.stat example, do you want this before each phase of the refresh?
But we want some sort of measure of "memory ruby thinks it's actively using"… is that the live object count?
{: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}total_allocated_objects - total_freed_objects sounds plausible, I think?
yup
I'll do both
I guess that's
heap_live_slots ¯\_(ツ)_/¯
slots aren't objects though
I'm not sure we care about the distinction
See how I implied I know what the distinction is, there? ;)
@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?
Shouldn't be too hard :laughing:
Hopefully the former?
that was ALL
line 2361 looks suspicious, not sure how big the objects are that it's duplicating on the split
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?
but we assumed you don't know what you're doing ;-)
sure, I'll try it in a second
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
@roliveri might have tests for it, maybe @Fryguy knows too
Another easy win by freezing the
'[' on the former 2383 (first line of tagAndKey)
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
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
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
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
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
No, I'm not using the broker with console
also that increases memory usage
or runner
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
ah, yes, i do the first
and wait for the VIMBroker to be ready
no,sorry, I don't use the broker
So might be better to use a brokerless provider (RHEVM)
I can try with a broker to see if it changes anythign
so without doing the cache patch, my rss memory change was ~385MiB for medium and now it's 462MiB
@akrzos what's "was" vs "now"? :confused:
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.rbnow == 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
ok, was about to ask :worried:
I'm going to put them into a ethercalc spreadsheet so we can read them more easily
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
@akrzos are you saying the timings are poor for both tuned and untuned or just one?
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
@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
@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/
m == memsize_of(object) for all objects on the line number
@jrafanie running benchmarks, without patching cache scope, timing drops dramatically
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
@jrafanie can you throw the class name into that report please?
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/
:heart:
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:
Some of these seem very odd that we'd be retaining them post-refresh :confused:
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) }
@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
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
@akrzos stop finding issues man ;)
(aka thanks)
@kbrock You guys are getting a week and half break :smirk:
:)