Bug 1220910
| Summary: | Initial/Delta Refreshes 27-65% of time in the ruby garbage collector depending on provider size | ||
|---|---|---|---|
| Product: | Red Hat CloudForms Management Engine | Reporter: | Alex Krzos <akrzos> |
| Component: | Performance | Assignee: | dmetzger |
| Status: | CLOSED ERRATA | QA Contact: | Jeff Teehan <jteehan> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 5.3.0 | CC: | akrzos, cpelland, jhardy, jprause, mfeifer, obarenbo, perfbz |
| Target Milestone: | GA | Flags: | akrzos:
needinfo-
akrzos: needinfo- |
| Target Release: | 5.6.0 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | 5.6.0.0 | Doc Type: | Bug Fix |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2016-06-29 14:54:59 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
| Bug Depends On: | 1290159 | ||
| Bug Blocks: | |||
| Attachments: | |||
I'd love to see the same stats with ManageIQ using ruby 2.0.0 and ruby 2.1.6 since ruby 2.1 introduced a generational garbage collector. 2.1 also added heap dumping support with allocation statistics http://samsaffron.com/archive/2015/03/31/debugging-memory-leaks-in-ruby so we can see where the object allocations are coming from. I can help get a MIQ appliance running with ruby 2.1.6. See above comment Ruby 2.0 results in. The garbage collector is still showing up at the most sampled function during profiling across all tested providers.
Using the same sized VMware providers and a 5.4 appliance with ruby 2.0, Delta Refreshes have the largest amount of change in them with the large provider: 58.6%(Ruby 1.9.3) vs 28.3%(Ruby 2.0.0). These reductions are not across the board. In some instances Ruby 2.0 spent more time in the garbage collector. Focusing on comparing Refresh with a VIMBroker, delta refreshes have an improvement for all 3 providers tested, as initial refreshes have a slight improvement for small and large.
Initial Refresh - First refresh after attaching an environment
Without VIMBroker:
Small --- Large
41.4%,37.7%,41.2% (S,M,L) of samples spent in the garbage_collector
with VIMBroker:
38.8%,53.2%,57.1% (S/M/L) of samples spent in the garbage collector
Delta Refresh - subsequent refreshes after initial refresh
Without VIMBroker:
38.7%,28.8%,31.4% (S/M/L) of samples spent in the garbage_collector
with VIMBroker:
25.8%,33.8%,28.3% (S/M/L) of samples spent in the garbage_collector
Raw Data:
vmware-small-init without VIMBroker:
[----] I, [2015-05-27T00:32:06.370645 #30419:11e7ea8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2488703727722168, :get_vc_data=>3.3433215618133545, :get_vc_data_ems_customization_specs=>0.005377531051635742, :filter_vc_data=>0.0002830028533935547, :get_vc_data_host_scsi=>0.6428117752075195, :get_vc_data_total=>4.249937534332275, :parse_vc_data=>1.575291395187378, :db_save_inventory=>10.339580059051514, :post_refresh_ems=>0.9120259284973145, :total_time=>17.077173233032227}
# pprof.rb --text profile-provider-init-vmware-small-0 | head -n 10
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-vmware-small-0.
Total: 1426 samples
591 41.4% 41.4% 591 41.4% garbage_collector
27 1.9% 43.3% 593 41.6% Kernel#require
27 1.9% 45.2% 28 2.0% Module#module_eval
17 1.2% 46.4% 17 1.2% String#split
15 1.1% 47.5% 15 1.1% Kernel#respond_to?
14 1.0% 48.5% 14 1.0% PGconn#async_exec
13 0.9% 49.4% 13 0.9% Class#logger
13 0.9% 50.3% 13 0.9% String#intern
11 0.8% 51.1% 24 1.7% Module#class_eval
vmware-small delta without VIMBroker:
[----] I, [2015-05-27T12:08:34.107813 #14081:813ea4] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.12441229820251465, :get_vc_data=>3.7540853023529053, :get_vc_data_ems_customization_specs=>0.004010677337646484, :filter_vc_data=>0.0002307891845703125, :get_vc_data_host_scsi=>0.675309419631958, :get_vc_data_total=>4.5660319328308105, :parse_vc_data=>0.07608509063720703, :db_save_inventory=>4.332095384597778, :post_refresh_ems=>0.019302845001220703, :total_time=>8.993860721588135}
# pprof.rb --text profile-provider-delta-vmware-small | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-vmware-small.
Total: 679 samples
263 38.7% 38.7% 263 38.7% garbage_collector
13 1.9% 40.6% 26 3.8% MiqVimInventory#splitPropPath
13 1.9% 42.6% 13 1.9% PGconn#async_exec
13 1.9% 44.5% 13 1.9% String#split
12 1.8% 46.2% 12 1.8% Nokogiri::XML::Node#children
10 1.5% 47.7% 13 1.9% Nokogiri::XML::Document.read_memory
8 1.2% 48.9% 8 1.2% Array#hash
8 1.2% 50.1% 46 6.8% VimService#unmarshal_response
7 1.0% 51.1% 7 1.0% Class#logger
vmware-medium-init without VIMBroker:
[----] I, [2015-05-27T00:49:36.218423 #34695:5ddea0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2598536014556885, :get_vc_data=>24.41530752182007, :get_vc_data_ems_customization_specs=>0.006153583526611328, :filter_vc_data=>0.00021910667419433594, :get_vc_data_host_scsi=>3.534564971923828, :get_vc_data_total=>28.223388671875, :parse_vc_data=>19.40038013458252, :db_save_inventory=>101.72533297538757, :post_refresh_ems=>7.237452983856201, :total_time=>156.58688044548035}
# pprof.rb --text profile-provider-init-vmware-medium-0 | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-vmware-medium-0.
Total: 12074 samples
4547 37.7% 37.7% 4547 37.7% garbage_collector
173 1.4% 39.1% 173 1.4% String#split
167 1.4% 40.5% 343 2.8% #<Module:0x00000007372970>#__temp__
143 1.2% 41.7% 300 2.5% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
142 1.2% 42.8% 2437 20.2% ActiveSupport::Callbacks#run_callbacks
131 1.1% 43.9% 131 1.1% Hash.[]
121 1.0% 44.9% 124 1.0% Kernel#respond_to?
120 1.0% 45.9% 120 1.0% Fixnum#to_s
115 1.0% 46.9% 396 3.3% ActiveRecord::AttributeMethods#respond_to?
vmware-medium delta without VIMBroker:
[----] I, [2015-05-27T12:40:53.588584 #16699:499ea4] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.12276983261108398, :get_vc_data=>26.51749897003174, :get_vc_data_ems_customization_specs=>0.0049266815185546875, :filter_vc_data=>0.0002770423889160156, :get_vc_data_host_scsi=>3.2299911975860596, :get_vc_data_total=>29.882575511932373, :parse_vc_data=>0.6520965099334717, :db_save_inventory=>40.89282512664795, :post_refresh_ems=>0.1143808364868164, :total_time=>71.5422112941742}
# pprof.rb --text profile-provider-delta-vmware-medium | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-vmware-medium.
Total: 5917 samples
1705 28.8% 28.8% 1705 28.8% garbage_collector
198 3.3% 32.2% 354 6.0% #<Module:0x00000004a0cea0>#__temp__
184 3.1% 35.3% 184 3.1% String#split
116 2.0% 37.2% 140 2.4% Nokogiri::XML::Node#children
113 1.9% 39.1% 113 1.9% PGconn#async_exec
97 1.6% 40.8% 424 7.2% ActiveRecord::Base#==
88 1.5% 42.3% 88 1.5% Module#===
87 1.5% 43.7% 457 7.7% VimService#unmarshal_response
76 1.3% 45.0% 258 4.4% MiqVimInventory#splitPropPath
vmware-large-init without VIMBroker:
[----] I, [2015-05-27T01:32:15.909851 #48352:50dea8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2611572742462158, :get_vc_data=>69.39091205596924, :get_vc_data_ems_customization_specs=>0.02052593231201172, :filter_vc_data=>0.00023174285888671875, :get_vc_data_host_scsi=>7.1732470989227295, :get_vc_data_total=>76.86632537841797, :parse_vc_data=>7.258993625640869, :db_save_inventory=>544.7598974704742, :post_refresh_ems=>22.129197359085083, :total_time=>651.0147733688354}
# pprof.rb --text profile-provider-init-vmware-large-1 | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-vmware-large-1.
Total: 59230 samples
24409 41.2% 41.2% 24409 41.2% garbage_collector
1748 3.0% 44.2% 3567 6.0% #<Module:0x000000075573a8>#__temp__
1209 2.0% 46.2% 2396 4.0% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
1110 1.9% 48.1% 1114 1.9% Hash.[]
991 1.7% 49.8% 10815 18.3% ActiveSupport::Callbacks#run_callbacks
965 1.6% 51.4% 10149 17.1% ActiveRecord::Inheritance::ClassMethods#instantiate
951 1.6% 53.0% 951 1.6% Module#===
935 1.6% 54.6% 7749 13.1% ActiveRecord::Base#init_with
838 1.4% 56.0% 2174 3.7% ActiveRecord::AttributeMethods#respond_to?
vmware-large delta without VIMBroker:
[----] I, [2015-05-27T13:02:33.522414 #20934:96fe9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.19585442543029785, :get_vc_data=>87.9742476940155, :get_vc_data_ems_customization_specs=>0.0061452388763427734, :filter_vc_data=>0.00024175643920898438, :get_vc_data_host_scsi=>8.485399007797241, :get_vc_data_total=>96.69029831886292, :parse_vc_data=>7.699193716049194, :db_save_inventory=>163.96813893318176, :post_refresh_ems=>0.32727527618408203, :total_time=>268.68523621559143}
# pprof.rb --text profile-provider-delta-vmware-large | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-vmware-large.
Total: 23202 samples
7256 31.3% 31.3% 7256 31.3% garbage_collector
2305 9.9% 41.2% 3792 16.3% #<Module:0x000000053a5548>#__temp__
949 4.1% 45.3% 4407 19.0% ActiveRecord::Base#==
740 3.2% 48.5% 740 3.2% Module#===
499 2.2% 50.6% 499 2.2% String#split
360 1.6% 52.2% 361 1.6% Hash#has_key?
347 1.5% 53.7% 1289 5.6% Class#value_to_integer
305 1.3% 55.0% 418 1.8% Nokogiri::XML::Node#children
281 1.2% 56.2% 281 1.2% PGconn#async_exec
----------------------------------------------------------------------------------------------------------------------------------
VIMBroker
----------------------------------------------------------------------------------------------------------------------------------
vmware-small-init with VIMBroker:
[----] I, [2015-05-26T23:01:49.414847 #4362:113fe9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.33099794387817383, :get_vc_data=>0.5826287269592285, :get_vc_data_ems_customization_specs=>0.008536338806152344, :filter_vc_data=>0.0002372264862060547, :get_vc_data_host_scsi=>0.7663960456848145, :get_vc_data_total=>1.6895389556884766, :parse_vc_data=>1.2298479080200195, :db_save_inventory=>9.95995831489563, :post_refresh_ems=>0.7662553787231445, :total_time=>13.645853281021118}
# pprof.rb --text profile-provider-init-broker-vmware-small-0 | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-broker-vmware-small-0.
Total: 1158 samples
449 38.8% 38.8% 449 38.8% garbage_collector
28 2.4% 41.2% 29 2.5% Module#module_eval
27 2.3% 43.5% 498 43.0% Kernel#require
14 1.2% 44.7% 29 2.5% Module#class_eval
13 1.1% 45.9% 13 1.1% Symbol#to_s
12 1.0% 46.9% 12 1.0% Kernel#respond_to?
12 1.0% 47.9% 12 1.0% String#_fast_gettext_old_format_m
11 0.9% 48.9% 11 0.9% PGconn#async_exec
9 0.8% 49.7% 18 1.6% ActiveRecord::Relation#initialize
vmware-small delta with VIMBroker:
[----] I, [2015-05-27T15:58:38.297686 #44633:c81ea0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.03277778625488281, :get_vc_data=>0.5825622081756592, :get_vc_data_ems_customization_specs=>0.009392976760864258, :filter_vc_data=>0.00034618377685546875, :get_vc_data_host_scsi=>0.8681252002716064, :get_vc_data_total=>1.4942381381988525, :parse_vc_data=>0.08681011199951172, :db_save_inventory=>4.8372485637664795, :post_refresh_ems=>0.023020029067993164, :total_time=>6.441631555557251}
# pprof.rb --text profile-provider-delta-broker-vmware-small | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-broker-vmware-small.
Total: 484 samples
125 25.8% 25.8% 125 25.8% garbage_collector
22 4.5% 30.4% 22 4.5% PGconn#async_exec
16 3.3% 33.7% 16 3.3% Class#logger
7 1.4% 35.1% 8 1.7% Marshal.load_without_autoload_missing_constants
7 1.4% 36.6% 7 1.4% Symbol#to_s
6 1.2% 37.8% 22 4.5% ActiveRecord::AttributeMethods::Dirty#write_attribute
6 1.2% 39.0% 8 1.7% Hash#[]=
6 1.2% 40.3% 6 1.2% Time#initialize
5 1.0% 41.3% 5 1.0% ActiveRecord::Delegation#auto_explain_threshold_in_seconds
vmware-medium-init with VIMBroker:
[----] I, [2015-05-26T23:29:30.821544 #12153:1257e9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.32448911666870117, :get_vc_data=>6.626133441925049, :get_vc_data_ems_customization_specs=>0.008968591690063477, :filter_vc_data=>0.00027680397033691406, :get_vc_data_host_scsi=>4.180689334869385, :get_vc_data_total=>11.141518115997314, :parse_vc_data=>3.881192922592163, :db_save_inventory=>133.833251953125, :post_refresh_ems=>9.47793960571289, :total_time=>158.33422565460205}
# pprof.rb --text profile-provider-init-broker-vmware-medium-1 | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-broker-vmware-medium-1.
Total: 13816 samples
7350 53.2% 53.2% 7350 53.2% garbage_collector
188 1.4% 54.6% 361 2.6% #<Module:0x00000009339bc8>#__temp__
145 1.0% 55.6% 145 1.0% Kernel#respond_to?
135 1.0% 56.6% 2281 16.5% ActiveSupport::Callbacks#run_callbacks
133 1.0% 57.5% 273 2.0% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
131 0.9% 58.5% 133 1.0% Hash.[]
120 0.9% 59.4% 1164 8.4% ActiveRecord::Inheritance::ClassMethods#instantiate
118 0.9% 60.2% 389 2.8% ActiveRecord::AttributeMethods#respond_to?
117 0.8% 61.1% 117 0.8% PGconn#async_exec
vmware-medium delta with VIMBroker:
[----] I, [2015-05-27T16:08:43.289816 #46779:b1de9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.028961181640625, :get_vc_data=>8.571406126022339, :get_vc_data_ems_customization_specs=>0.010356426239013672, :filter_vc_data=>0.0003249645233154297, :get_vc_data_host_scsi=>4.592574596405029, :get_vc_data_total=>13.204903364181519, :parse_vc_data=>1.0549991130828857, :db_save_inventory=>53.98538637161255, :post_refresh_ems=>0.56260085105896, :total_time=>68.80820918083191}
# pprof.rb --text profile-provider-delta-broker-vmware-medium | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-broker-vmware-medium.
Total: 5436 samples
1836 33.8% 33.8% 1836 33.8% garbage_collector
229 4.2% 38.0% 403 7.4% #<Module:0x00000005714e68>#__temp__
147 2.7% 40.7% 147 2.7% PGconn#async_exec
109 2.0% 42.7% 447 8.2% ActiveRecord::Base#==
81 1.5% 44.2% 81 1.5% Module#===
78 1.4% 45.6% 134 2.5% Hash#[]=
70 1.3% 46.9% 244 4.5% ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
70 1.3% 48.2% 70 1.3% Class#logger
66 1.2% 49.4% 67 1.2% Marshal.load_without_autoload_missing_constants
vmware-large-init with VIMBroker:
[----] I, [2015-05-27T00:06:43.053988 #23187:86be9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.31658482551574707, :get_vc_data=>17.77312135696411, :get_vc_data_ems_customization_specs=>0.019414901733398438, :filter_vc_data=>0.0002372264862060547, :get_vc_data_host_scsi=>7.81794285774231, :get_vc_data_total=>25.92831063270569, :parse_vc_data=>8.788389205932617, :db_save_inventory=>714.5265052318573, :post_refresh_ems=>29.040082693099976, :total_time=>778.2835595607758}
# pprof.rb --text profile-provider-init-broker-vmware-large-1 | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-init-broker-vmware-large-1.
Total: 71670 samples
40933 57.1% 57.1% 40933 57.1% garbage_collector
1560 2.2% 59.3% 3268 4.6% #<Module:0x00000007ce86f8>#__temp__
1292 1.8% 61.1% 2445 3.4% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
1193 1.7% 62.8% 1196 1.7% Hash.[]
971 1.4% 64.1% 10559 14.7% ActiveSupport::Callbacks#run_callbacks
927 1.3% 65.4% 9905 13.8% ActiveRecord::Inheritance::ClassMethods#instantiate
844 1.2% 66.6% 7653 10.7% ActiveRecord::Base#init_with
836 1.2% 67.7% 2030 2.8% ActiveRecord::AttributeMethods#respond_to?
794 1.1% 68.9% 794 1.1% Module#===
vmware-large delta with VIMBroker:
[----] I, [2015-05-27T16:34:24.196550 #51652:ce9e9c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.04047369956970215, :get_vc_data=>35.931872606277466, :get_vc_data_ems_customization_specs=>0.0164487361907959, :filter_vc_data=>0.00038909912109375, :get_vc_data_host_scsi=>7.180527210235596, :get_vc_data_total=>43.17105054855347, :parse_vc_data=>6.684070587158203, :db_save_inventory=>239.9114544391632, :post_refresh_ems=>0.44094181060791016, :total_time=>290.2079060077667}
# pprof.rb --text profile-provider-delta-broker-vmware-large | head
Using local file /opt/rh/ruby200/root/usr/bin/ruby.
Using local file profile-provider-delta-broker-vmware-large.
Total: 24174 samples
6836 28.3% 28.3% 6836 28.3% garbage_collector
3504 14.5% 42.8% 5471 22.6% #<Module:0x00000005a74888>#__temp__
934 3.9% 46.6% 5608 23.2% ActiveRecord::Base#==
826 3.4% 50.1% 826 3.4% Module#===
622 2.6% 52.6% 623 2.6% Hash#has_key?
377 1.6% 54.2% 1484 6.1% Class#value_to_integer
370 1.5% 55.7% 1355 5.6% Array#select
370 1.5% 57.2% 370 1.5% PGconn#async_exec
311 1.3% 58.5% 311 1.3% String#to_i
Created attachment 1031208 [details]
Graphs Comparing % spent in garbage collector
Excellent results from profiling EmsRefresh with Ruby 2.1.6. I expect this is because of the Minor/Major GC in Ruby 2.1
In summary, all tests showed a large improvement in amount of time spent in the garbage collector. I had to use stackprof for profiling in place of perftools.rb this time. See attached spreadsheet for comparison data including timings on refresh exposed in evm.log. The only anomaly in this data is the timings for refresh with ruby 2.0 on the small provider without a Broker.
Raw Data:
vmware-small-init without VIMBroker:
[----] I, [2015-06-07T07:18:48.620417 #35176:3fa41be793d0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1654064655303955, :get_vc_data=>2.4336888790130615, :get_vc_data_ems_customization_specs=>0.004213571548461914, :filter_vc_data=>0.00021028518676757812, :get_vc_data_host_scsi=>0.3020975589752197, :get_vc_data_total=>2.9096384048461914, :parse_vc_data=>17.866724729537964, :db_save_inventory=>6.085234642028809, :post_refresh_ems=>0.452589750289917, :total_time=>27.314438104629517}
# stackprof --text stackprof-provider-init-vmware-small-0
==================================
Mode: cpu(1000)
Samples: 7609 (1.37% miss rate)
GC: 1124 (14.77%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
247 (3.2%) 247 (3.2%) block in MiqVimInventory#splitPropPath
1019 (13.4%) 166 (2.2%) block in ActiveSupport::Dependencies::Loadable#require
761 (10.0%) 163 (2.1%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
153 (2.0%) 153 (2.0%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
150 (2.0%) 150 (2.0%) Nokogiri::XML::Document#decorate
279 (3.7%) 117 (1.5%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
91 (1.2%) 91 (1.2%) ActiveRecord::Base.logger
80 (1.1%) 80 (1.1%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
92 (1.2%) 76 (1.0%) Psych::ScalarScanner#tokenize
76 (1.0%) 76 (1.0%) ActiveRecord::Associations#association_instance_get
75 (1.0%) 75 (1.0%) String#%
69 (0.9%) 69 (0.9%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
67 (0.9%) 67 (0.9%) block in ActiveRecord::Relation#initialize
66 (0.9%) 66 (0.9%) block in ActiveRecord::Relation#initialize
89 (1.2%) 62 (0.8%) ActiveModel::AttributeMethods#respond_to?
61 (0.8%) 61 (0.8%) ActiveRecord::AttributeMethods::ClassMethods#method_defined_within?
61 (0.8%) 61 (0.8%) Psych::Nodes::Scalar#initialize
1531 (20.1%) 61 (0.8%) block in VimService#unmarshal_response
224 (2.9%) 60 (0.8%) ActiveRecord::LogSubscriber#sql
58 (0.8%) 58 (0.8%) ActiveModel::Dirty#changed_attributes
2164 (28.4%) 57 (0.7%) VimService#unmarshal_response
58 (0.8%) 56 (0.7%) ActiveRecord::DynamicFinderMatch.match
56 (0.7%) 56 (0.7%) VimString#xsiType=
55 (0.7%) 55 (0.7%) #<Module:0x007f483cd962b0>.escape_punctuation
5516 (72.5%) 55 (0.7%) ActiveSupport::Callbacks#run_callbacks
1380 (18.1%) 51 (0.7%) Psych::Visitors::Visitor#visit
47 (0.6%) 47 (0.6%) Arel::Visitors::Visitor#dispatch
123 (1.6%) 47 (0.6%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
58 (0.8%) 46 (0.6%) ActiveRecord::ModelSchema::ClassMethods#columns_hash
41 (0.5%) 41 (0.5%) ActiveRecord::Scoping::ClassMethods#current_scope
vmware-small delta without VIMBroker:
[----] I, [2015-06-07T08:16:15.945391 #61471:3f8001dcf3c8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1182851791381836, :get_vc_data=>2.6296844482421875, :get_vc_data_ems_customization_specs=>0.012856721878051758, :filter_vc_data=>0.0001842975616455078, :get_vc_data_host_scsi=>0.3862645626068115, :get_vc_data_total=>3.1593573093414307, :parse_vc_data=>0.07383966445922852, :db_save_inventory=>3.1412389278411865, :post_refresh_ems=>0.017825841903686523, :total_time=>6.3924431800842285}
# stackprof --text stackprof-provider-delta-vmware-small
==================================
Mode: cpu(1000)
Samples: 3997 (3.24% miss rate)
GC: 502 (12.56%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
268 (6.7%) 268 (6.7%) block in MiqVimInventory#splitPropPath
232 (5.8%) 180 (4.5%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
168 (4.2%) 168 (4.2%) Nokogiri::XML::Document#decorate
121 (3.0%) 121 (3.0%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
243 (6.1%) 99 (2.5%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
81 (2.0%) 81 (2.0%) ActiveRecord::Base.logger
67 (1.7%) 67 (1.7%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
65 (1.6%) 65 (1.6%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
64 (1.6%) 64 (1.6%) ActiveRecord::Associations#association_instance_get
62 (1.6%) 62 (1.6%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
1531 (38.3%) 60 (1.5%) block in VimService#unmarshal_response
59 (1.5%) 59 (1.5%) VimString#xsiType=
2160 (54.0%) 54 (1.4%) VimService#unmarshal_response
47 (1.2%) 47 (1.2%) String#%
584 (14.6%) 47 (1.2%) ActiveSupport::Notifications::Instrumenter#instrument
50 (1.3%) 42 (1.1%) ActiveModel::AttributeMethods#respond_to?
40 (1.0%) 40 (1.0%) MiqVimInventory#tagAndKey
269 (6.7%) 36 (0.9%) MiqVimInventory#applySelSpec
33 (0.8%) 33 (0.8%) block in ActiveRecord::Relation#initialize
52 (1.3%) 31 (0.8%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
31 (0.8%) 31 (0.8%) ActiveModel::Dirty#changed_attributes
30 (0.8%) 30 (0.8%) block (2 levels) in ActiveRecord::Base.connection_handler=
29 (0.7%) 29 (0.7%) Nokogiri::XML::Document#initialize
1409 (35.3%) 28 (0.7%) ActiveSupport::Callbacks#run_callbacks
28 (0.7%) 28 (0.7%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
27 (0.7%) 27 (0.7%) Nokogiri::XML::Node#text?
26 (0.7%) 26 (0.7%) block in ActiveRecord::Result#hash_rows
26 (0.7%) 26 (0.7%) block in ActiveRecord::Relation#initialize
70 (1.8%) 26 (0.7%) Logger#add
46 (1.2%) 26 (0.7%) ActiveSupport::Notifications::Event#initialize
vmware-medium-init without VIMBroker:
[----] I, [2015-06-07T07:31:16.086710 #39083:3fcdf8c4b3cc] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1894855499267578, :get_vc_data=>20.03423810005188, :get_vc_data_ems_customization_specs=>0.005224704742431641, :filter_vc_data=>0.0002110004425048828, :get_vc_data_host_scsi=>2.129763126373291, :get_vc_data_total=>22.367910385131836, :parse_vc_data=>31.86851739883423, :db_save_inventory=>63.06538224220276, :post_refresh_ems=>4.351910591125488, :total_time=>121.65393495559692}
# stackprof --text stackprof-provider-init-vmware-medium-0
==================================
Mode: cpu(1000)
Samples: 70026 (1.48% miss rate)
GC: 11978 (17.11%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4258 (6.1%) 4258 (6.1%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
2308 (3.3%) 2308 (3.3%) block in MiqVimInventory#splitPropPath
2089 (3.0%) 2083 (3.0%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
1722 (2.5%) 1722 (2.5%) block in ActiveRecord::Result#hash_rows
6090 (8.7%) 1436 (2.1%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
1317 (1.9%) 1317 (1.9%) Nokogiri::XML::Document#decorate
1261 (1.8%) 1261 (1.8%) block in ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
48900 (69.8%) 1242 (1.8%) ActiveSupport::Callbacks#run_callbacks
1392 (2.0%) 1212 (1.7%) ActiveModel::AttributeMethods#respond_to?
2010 (2.9%) 1081 (1.5%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
861 (1.2%) 861 (1.2%) ActiveRecord::Base.logger
809 (1.2%) 809 (1.2%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
1267 (1.8%) 764 (1.1%) ActiveRecord::ModelSchema::ClassMethods#inheritance_column
707 (1.0%) 707 (1.0%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
698 (1.0%) 698 (1.0%) ActiveRecord::Associations#association_instance_get
673 (1.0%) 673 (1.0%) block in ActiveRecord::Relation#initialize
647 (0.9%) 647 (0.9%) block in ActiveRecord::Relation#initialize
2206 (3.2%) 624 (0.9%) ActiveRecord::LogSubscriber#sql
596 (0.9%) 596 (0.9%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#result_as_array
535 (0.8%) 535 (0.8%) #<Module:0x007f9bf6a581a8>.escape_punctuation
12317 (17.6%) 493 (0.7%) block in VimService#unmarshal_response
17427 (24.9%) 479 (0.7%) VimService#unmarshal_response
472 (0.7%) 472 (0.7%) String#%
467 (0.7%) 467 (0.7%) ActiveModel::Dirty#changed_attributes
466 (0.7%) 466 (0.7%) VimString#xsiType=
409 (0.6%) 409 (0.6%) #<Module:0x007f9bfb27dd70>#__temp__
1316 (1.9%) 398 (0.6%) block in ActiveRecord::AttributeMethods#arel_attributes_values
399 (0.6%) 391 (0.6%) ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
377 (0.5%) 377 (0.5%) Arel::Visitors::Visitor#dispatch
389 (0.6%) 370 (0.5%) ActiveRecord::ModelSchema::ClassMethods#columns_hash
vmware-medium-delta without VIMBroker:
[----] I, [2015-06-07T08:22:15.754319 #62895:3fa061c1d3c4] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1385958194732666, :get_vc_data=>21.463000297546387, :get_vc_data_ems_customization_specs=>0.006472587585449219, :filter_vc_data=>0.0002048015594482422, :get_vc_data_host_scsi=>2.3411877155303955, :get_vc_data_total=>23.955264568328857, :parse_vc_data=>0.8851838111877441, :db_save_inventory=>30.385136365890503, :post_refresh_ems=>0.10848021507263184, :total_time=>55.3342969417572}
# stackprof --text stackprof-provider-delta-vmware-medium
==================================
Mode: cpu(1000)
Samples: 38889 (4.50% miss rate)
GC: 5209 (13.39%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
3541 (9.1%) 3541 (9.1%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
2314 (6.0%) 2314 (6.0%) block in MiqVimInventory#splitPropPath
2455 (6.3%) 1927 (5.0%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
1581 (4.1%) 1581 (4.1%) Nokogiri::XML::Document#decorate
2260 (5.8%) 1034 (2.7%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
802 (2.1%) 802 (2.1%) ActiveRecord::Base.logger
649 (1.7%) 649 (1.7%) ActiveRecord::Associations#association_instance_get
640 (1.6%) 640 (1.6%) #<Module:0x007f40c8845278>#__temp__
19866 (51.1%) 604 (1.6%) VimService#unmarshal_response
548 (1.4%) 548 (1.4%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
13988 (36.0%) 511 (1.3%) block in VimService#unmarshal_response
499 (1.3%) 499 (1.3%) VimString#xsiType=
465 (1.2%) 465 (1.2%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
411 (1.1%) 411 (1.1%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
2658 (6.8%) 359 (0.9%) MiqVimInventory#applySelSpec
350 (0.9%) 350 (0.9%) String#%
4926 (12.7%) 348 (0.9%) ActiveSupport::Notifications::Instrumenter#instrument
312 (0.8%) 312 (0.8%) VimHash#xsiType=
307 (0.8%) 307 (0.8%) block in ActiveRecord::Relation#initialize
340 (0.9%) 304 (0.8%) ActiveModel::AttributeMethods#respond_to?
303 (0.8%) 303 (0.8%) MiqVimInventory#tagAndKey
292 (0.8%) 292 (0.8%) block in ActiveRecord::Relation#initialize
522 (1.3%) 289 (0.7%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
270 (0.7%) 270 (0.7%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
12530 (32.2%) 269 (0.7%) ActiveSupport::Callbacks#run_callbacks
426 (1.1%) 257 (0.7%) ActiveSupport::Notifications::Event#initialize
250 (0.6%) 250 (0.6%) block in ActiveRecord::Result#hash_rows
244 (0.6%) 244 (0.6%) block (2 levels) in ActiveRecord::Base.connection_handler=
243 (0.6%) 243 (0.6%) ActiveModel::Dirty#changed_attributes
363 (0.9%) 241 (0.6%) MoreCoreExtensions::Shared::Nested#fetch_path
vmware-large-init without VIMBroker:
[----] I, [2015-06-07T07:51:43.686556 #46730:3f97348a73d8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.18778276443481445, :get_vc_data=>55.22791862487793, :get_vc_data_ems_customization_specs=>0.005342006683349609, :filter_vc_data=>0.0002560615539550781, :get_vc_data_host_scsi=>6.037866115570068, :get_vc_data_total=>61.46628713607788, :parse_vc_data=>34.22565221786499, :db_save_inventory=>345.9134199619293, :post_refresh_ems=>13.302656888961792, :total_time=>454.90829038619995}
# stackprof --text stackprof-provider-init-vmware-large-0
==================================
Mode: cpu(1000)
Samples: 344127 (5.16% miss rate)
GC: 80950 (23.52%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
35170 (10.2%) 35170 (10.2%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
16721 (4.9%) 16716 (4.9%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
16672 (4.8%) 16672 (4.8%) block in ActiveRecord::Result#hash_rows
11109 (3.2%) 11109 (3.2%) block in ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
189345 (55.0%) 10520 (3.1%) ActiveSupport::Callbacks#run_callbacks
7741 (2.2%) 7173 (2.1%) ActiveModel::AttributeMethods#respond_to?
6298 (1.8%) 6298 (1.8%) block in MiqVimInventory#splitPropPath
8796 (2.6%) 5402 (1.6%) ActiveRecord::ModelSchema::ClassMethods#inheritance_column
18216 (5.3%) 4604 (1.3%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
4206 (1.2%) 4206 (1.2%) Nokogiri::XML::Document#decorate
4020 (1.2%) 4020 (1.2%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
3655 (1.1%) 3655 (1.1%) #<Module:0x007f2e738cacc8>#__temp__
6397 (1.9%) 3449 (1.0%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
3208 (0.9%) 3208 (0.9%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#result_as_array
2879 (0.8%) 2879 (0.8%) Relationship#_run__204853233118116279__find__2885404555403672021__callbacks
2743 (0.8%) 2743 (0.8%) Relationship#_run__204853233118116279__initialize__2885404555403672021__callbacks
2639 (0.8%) 2639 (0.8%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
2469 (0.7%) 2454 (0.7%) ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
2442 (0.7%) 2442 (0.7%) #<Module:0x007f2e6b86c6a8>.enabled
2382 (0.7%) 2382 (0.7%) ActiveRecord::Base.logger
2231 (0.6%) 2231 (0.6%) block in ActiveRecord::Relation#initialize
2162 (0.6%) 2162 (0.6%) ActiveRecord::Associations#association_instance_get
2081 (0.6%) 2081 (0.6%) block in ActiveRecord::Relation#initialize
2006 (0.6%) 2006 (0.6%) NilClass#blank?
6625 (1.9%) 1967 (0.6%) ActiveRecord::LogSubscriber#sql
1879 (0.5%) 1879 (0.5%) #<Module:0x007f2e69950bc0>.escape_punctuation
1849 (0.5%) 1849 (0.5%) ActiveRecord::Locking::Optimistic::ClassMethods#locking_column
1996 (0.6%) 1811 (0.5%) block in RelationshipMixin#add_children
1637 (0.5%) 1637 (0.5%) ActiveModel::Dirty#changed_attributes
4049 (1.2%) 1567 (0.5%) #<Module:0x007f2e738cacc8>#__temp__
vmware-large-delta without VIMBroker:
[----] I, [2015-06-07T08:36:06.837516 #1754:3fafa05073c0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.16749024391174316, :get_vc_data=>64.4425790309906, :get_vc_data_ems_customization_specs=>0.005644321441650391, :filter_vc_data=>0.00024247169494628906, :get_vc_data_host_scsi=>5.037655830383301, :get_vc_data_total=>69.66355395317078, :parse_vc_data=>37.16284155845642, :db_save_inventory=>120.42639875411987, :post_refresh_ems=>0.32381486892700195, :total_time=>227.57688093185425}
# stackprof --text stackprof-provider-delta-vmware-large
==================================
Mode: cpu(1000)
Samples: 152761 (4.03% miss rate)
GC: 25795 (16.89%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
31626 (20.7%) 31626 (20.7%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
6635 (4.3%) 6635 (4.3%) block in MiqVimInventory#splitPropPath
5590 (3.7%) 5590 (3.7%) #<Module:0x007f5f441f9fa0>#__temp__
6993 (4.6%) 5445 (3.6%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
4648 (3.0%) 4648 (3.0%) Nokogiri::XML::Document#decorate
6508 (4.3%) 2906 (1.9%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
2243 (1.5%) 2243 (1.5%) ActiveRecord::Base.logger
1874 (1.2%) 1874 (1.2%) ActiveRecord::Associations#association_instance_get
58755 (38.5%) 1713 (1.1%) VimService#unmarshal_response
1699 (1.1%) 1699 (1.1%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
41411 (27.1%) 1560 (1.0%) block in VimService#unmarshal_response
1486 (1.0%) 1486 (1.0%) VimString#xsiType=
1322 (0.9%) 1322 (0.9%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
1232 (0.8%) 1232 (0.8%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
1656 (1.1%) 1149 (0.8%) MoreCoreExtensions::Shared::Nested#fetch_path
6683 (4.4%) 1101 (0.7%) block (2 levels) in EmsRefresh::SaveInventory#save_vms_inventory
1043 (0.7%) 1043 (0.7%) Numeric#blank?
8140 (5.3%) 1029 (0.7%) MiqVimInventory#applySelSpec
14590 (9.6%) 1028 (0.7%) ActiveSupport::Notifications::Instrumenter#instrument
1002 (0.7%) 1002 (0.7%) String#%
965 (0.6%) 965 (0.6%) block in ActiveRecord::Relation#initialize
953 (0.6%) 953 (0.6%) MiqVimInventory#tagAndKey
35777 (23.4%) 943 (0.6%) ActiveSupport::Callbacks#run_callbacks
897 (0.6%) 897 (0.6%) block in ActiveRecord::Relation#initialize
1291 (0.8%) 888 (0.6%) ActiveSupport::Notifications::Event#initialize
880 (0.6%) 880 (0.6%) VimHash#xsiType=
960 (0.6%) 875 (0.6%) ActiveModel::AttributeMethods#respond_to?
1609 (1.1%) 868 (0.6%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
5729 (3.8%) 830 (0.5%) block in ActiveRecord::AttributeMethods#attributes
812 (0.5%) 812 (0.5%) block (2 levels) in ActiveRecord::Base.connection_handler=
----------------------------------------------------------------------------------------------------------------------------------
VIMBroker
----------------------------------------------------------------------------------------------------------------------------------
vmware-small-init with VIMBroker:
[----] I, [2015-06-07T08:49:22.758445 #14369:3fa2c154d3c0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.14875078201293945, :get_vc_data=>0.36829710006713867, :get_vc_data_ems_customization_specs=>0.008398294448852539, :filter_vc_data=>0.00019884109497070312, :get_vc_data_host_scsi=>0.4580855369567871, :get_vc_data_total=>0.9845137596130371, :parse_vc_data=>1.3824570178985596, :db_save_inventory=>6.1001877784729, :post_refresh_ems=>0.46346426010131836, :total_time=>8.930861473083496}
# stackprof --text stackprof-provider-init-broker-vmware-small-2
==================================
Mode: cpu(1000)
Samples: 6327 (1.02% miss rate)
GC: 738 (11.66%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
765 (12.1%) 172 (2.7%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
994 (15.7%) 159 (2.5%) block in ActiveSupport::Dependencies::Loadable#require
297 (4.7%) 140 (2.2%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
125 (2.0%) 125 (2.0%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
103 (1.6%) 103 (1.6%) ActiveRecord::Base.logger
91 (1.4%) 81 (1.3%) Psych::ScalarScanner#tokenize
80 (1.3%) 80 (1.3%) block in ActiveRecord::Relation#initialize
79 (1.2%) 79 (1.2%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
74 (1.2%) 74 (1.2%) block in ActiveRecord::Relation#initialize
72 (1.1%) 72 (1.1%) String#%
75 (1.2%) 70 (1.1%) ActiveRecord::DynamicFinderMatch.match
5389 (85.2%) 69 (1.1%) ActiveSupport::Callbacks#run_callbacks
68 (1.1%) 68 (1.1%) #<Module:0x007f458531ad68>.escape_punctuation
245 (3.9%) 67 (1.1%) ActiveRecord::LogSubscriber#sql
66 (1.0%) 66 (1.0%) ActiveRecord::Associations#association_instance_get
90 (1.4%) 64 (1.0%) ActiveModel::AttributeMethods#respond_to?
61 (1.0%) 61 (1.0%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
60 (0.9%) 60 (0.9%) ActiveModel::Dirty#changed_attributes
58 (0.9%) 58 (0.9%) Psych::Nodes::Scalar#initialize
181 (2.9%) 57 (0.9%) ActiveModel::AttributeMethods::ClassMethods#define_optimized_call
54 (0.9%) 54 (0.9%) ActiveRecord::AttributeMethods::ClassMethods#method_defined_within?
65 (1.0%) 51 (0.8%) ActiveRecord::ModelSchema::ClassMethods#columns_hash
1322 (20.9%) 50 (0.8%) Psych::Visitors::Visitor#visit
172 (2.7%) 42 (0.7%) block in ActiveRecord::AttributeMethods#arel_attributes_values
41 (0.6%) 41 (0.6%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
461 (7.3%) 40 (0.6%) Arel::Visitors::Visitor#visit
37 (0.6%) 37 (0.6%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
37 (0.6%) 37 (0.6%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
36 (0.6%) 36 (0.6%) block in ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
35 (0.6%) 35 (0.6%) ActiveRecord::Persistence#new_record?
vmware-small-delta with VIMBroker:
[----] I, [2015-06-07T09:47:29.890843 #35403:3ff1f9c693c0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.014404296875, :get_vc_data=>0.42522573471069336, :get_vc_data_ems_customization_specs=>0.008125066757202148, :filter_vc_data=>0.0001952648162841797, :get_vc_data_host_scsi=>0.41916346549987793, :get_vc_data_total=>0.8678655624389648, :parse_vc_data=>0.07969403266906738, :db_save_inventory=>2.817840814590454, :post_refresh_ems=>0.017352581024169922, :total_time=>3.7829461097717285}
# stackprof --text stackprof-provider-delta-broker-vmware-small
==================================
Mode: cpu(1000)
Samples: 2539 (1.86% miss rate)
GC: 117 (4.61%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
237 (9.3%) 179 (7.1%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
244 (9.6%) 111 (4.4%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
93 (3.7%) 93 (3.7%) ActiveRecord::Base.logger
76 (3.0%) 76 (3.0%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
63 (2.5%) 63 (2.5%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
62 (2.4%) 62 (2.4%) ActiveRecord::Associations#association_instance_get
58 (2.3%) 58 (2.3%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
44 (1.7%) 44 (1.7%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
575 (22.6%) 42 (1.7%) ActiveSupport::Notifications::Instrumenter#instrument
52 (2.0%) 40 (1.6%) ActiveSupport::Notifications::Event#initialize
39 (1.5%) 39 (1.5%) String#%
36 (1.4%) 36 (1.4%) block in ActiveRecord::Relation#initialize
68 (2.7%) 36 (1.4%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
1358 (53.5%) 33 (1.3%) ActiveSupport::Callbacks#run_callbacks
33 (1.3%) 33 (1.3%) block in ActiveRecord::Relation#initialize
31 (1.2%) 31 (1.2%) ActiveModel::Dirty#changed_attributes
28 (1.1%) 28 (1.1%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
27 (1.1%) 27 (1.1%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
211 (8.3%) 26 (1.0%) block in ActiveRecord::AttributeMethods#attributes
26 (1.0%) 26 (1.0%) ActiveRecord::Persistence#new_record?
80 (3.2%) 25 (1.0%) Logger#add
24 (0.9%) 24 (0.9%) block in Logger::LogDevice#write
34 (1.3%) 24 (0.9%) ActiveModel::AttributeMethods#respond_to?
23 (0.9%) 23 (0.9%) block (2 levels) in ActiveRecord::Base.connection_handler=
22 (0.9%) 22 (0.9%) ActiveRecord::Scoping::ClassMethods#current_scope
21 (0.8%) 21 (0.8%) block in ActiveRecord::Result#hash_rows
21 (0.8%) 21 (0.8%) block in ActiveRecord::Result#hash_rows
178 (7.0%) 20 (0.8%) ActiveRecord::LogSubscriber#sql
304 (12.0%) 20 (0.8%) Arel::Visitors::Visitor#visit
16 (0.6%) 16 (0.6%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#result_as_array
vmware-medium-init with VIMBroker:
[----] I, [2015-06-07T09:00:48.555359 #18773:3fd3e17833c8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.14754295349121094, :get_vc_data=>3.992305040359497, :get_vc_data_ems_customization_specs=>0.007950067520141602, :filter_vc_data=>0.00019860267639160156, :get_vc_data_host_scsi=>2.11910080909729, :get_vc_data_total=>6.267833232879639, :parse_vc_data=>4.4876673221588135, :db_save_inventory=>64.85116648674011, :post_refresh_ems=>4.584681749343872, :total_time=>80.19156503677368}
# stackprof --text stackprof-provider-init-broker-vmware-medium-1
==================================
Mode: cpu(1000)
Samples: 61165 (1.05% miss rate)
GC: 8959 (14.65%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4161 (6.8%) 4161 (6.8%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
2564 (4.2%) 2023 (3.3%) ActiveRecord::ModelSchema::ClassMethods#inheritance_column
1949 (3.2%) 1946 (3.2%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
1887 (3.1%) 1681 (2.7%) ActiveModel::AttributeMethods#respond_to?
1554 (2.5%) 1554 (2.5%) block in ActiveRecord::Result#hash_rows
6122 (10.0%) 1441 (2.4%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
1358 (2.2%) 1358 (2.2%) block in ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
49973 (81.7%) 1293 (2.1%) ActiveSupport::Callbacks#run_callbacks
2021 (3.3%) 1034 (1.7%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
829 (1.4%) 829 (1.4%) ActiveRecord::Base.logger
720 (1.2%) 720 (1.2%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
699 (1.1%) 699 (1.1%) block in ActiveRecord::Relation#initialize
696 (1.1%) 696 (1.1%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
667 (1.1%) 667 (1.1%) block in ActiveRecord::Relation#initialize
654 (1.1%) 654 (1.1%) ActiveRecord::Associations#association_instance_get
2108 (3.4%) 592 (1.0%) ActiveRecord::LogSubscriber#sql
569 (0.9%) 569 (0.9%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#result_as_array
532 (0.9%) 532 (0.9%) #<Module:0x007fa7c8049238>.escape_punctuation
475 (0.8%) 475 (0.8%) ActiveModel::Dirty#changed_attributes
465 (0.8%) 459 (0.8%) ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
430 (0.7%) 430 (0.7%) String#%
1413 (2.3%) 426 (0.7%) block in ActiveRecord::AttributeMethods#arel_attributes_values
411 (0.7%) 398 (0.7%) ActiveRecord::ModelSchema::ClassMethods#columns_hash
391 (0.6%) 391 (0.6%) #<Module:0x007fa7ceb90618>#__temp__
591 (1.0%) 352 (0.6%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
18623 (30.4%) 351 (0.6%) ActiveSupport::Notifications::Instrumenter#instrument
347 (0.6%) 347 (0.6%) Arel::Visitors::Visitor#dispatch
345 (0.6%) 345 (0.6%) block (2 levels) in ActiveRecord::Base.serialized_attributes=
332 (0.5%) 332 (0.5%) #<Module:0x007fa7c560d9d8>.enabled
328 (0.5%) 328 (0.5%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
vmware-medium-delta with VIMBroker:
[----] I, [2015-06-07T09:53:42.520649 #37362:3f8b5f6ab3d0] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.023422718048095703, :get_vc_data=>3.897568464279175, :get_vc_data_ems_customization_specs=>0.009426593780517578, :filter_vc_data=>0.00019359588623046875, :get_vc_data_host_scsi=>2.462357759475708, :get_vc_data_total=>6.39369797706604, :parse_vc_data=>0.6064996719360352, :db_save_inventory=>29.34122371673584, :post_refresh_ems=>0.10328054428100586, :total_time=>36.44498801231384}
# stackprof --text stackprof-provider-delta-broker-vmware-medium
==================================
Mode: cpu(1000)
Samples: 26743 (2.26% miss rate)
GC: 1925 (7.20%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
3580 (13.4%) 3580 (13.4%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
2320 (8.7%) 1810 (6.8%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
2235 (8.4%) 1045 (3.9%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
753 (2.8%) 753 (2.8%) ActiveRecord::Base.logger
615 (2.3%) 615 (2.3%) ActiveRecord::Associations#association_instance_get
561 (2.1%) 561 (2.1%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
495 (1.9%) 495 (1.9%) #<Module:0x007f16ca7d9000>#__temp__
478 (1.8%) 478 (1.8%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
439 (1.6%) 439 (1.6%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
4919 (18.4%) 337 (1.3%) ActiveSupport::Notifications::Instrumenter#instrument
321 (1.2%) 321 (1.2%) String#%
315 (1.2%) 315 (1.2%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
302 (1.1%) 302 (1.1%) block in ActiveRecord::Relation#initialize
433 (1.6%) 286 (1.1%) ActiveSupport::Notifications::Event#initialize
12150 (45.4%) 279 (1.0%) ActiveSupport::Callbacks#run_callbacks
271 (1.0%) 271 (1.0%) block in ActiveRecord::Relation#initialize
291 (1.1%) 262 (1.0%) ActiveModel::AttributeMethods#respond_to?
466 (1.7%) 260 (1.0%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
257 (1.0%) 257 (1.0%) block (2 levels) in ActiveRecord::Base.connection_handler=
248 (0.9%) 248 (0.9%) ActiveModel::Dirty#changed_attributes
322 (1.2%) 225 (0.8%) MoreCoreExtensions::Shared::Nested#fetch_path
1909 (7.1%) 223 (0.8%) block in ActiveRecord::AttributeMethods#attributes
209 (0.8%) 209 (0.8%) block in ActiveRecord::Result#hash_rows
199 (0.7%) 199 (0.7%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
187 (0.7%) 187 (0.7%) MonitorMixin#mon_enter
666 (2.5%) 178 (0.7%) Logger#add
168 (0.6%) 168 (0.6%) ActiveRecord::Persistence#new_record?
167 (0.6%) 163 (0.6%) block in Logger::LogDevice#write
1379 (5.2%) 158 (0.6%) ActiveRecord::LogSubscriber#sql
2187 (8.2%) 133 (0.5%) Arel::Visitors::Visitor#visit
vmware-large-init with VIMBroker:
[----] I, [2015-06-07T09:18:53.024783 #25026:3fae357373b4] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.15125584602355957, :get_vc_data=>13.845446109771729, :get_vc_data_ems_customization_specs=>0.010507345199584961, :filter_vc_data=>0.0002193450927734375, :get_vc_data_host_scsi=>5.392552137374878, :get_vc_data_total=>19.401209592819214, :parse_vc_data=>30.18648409843445, :db_save_inventory=>388.960236787796, :post_refresh_ems=>17.170814037322998, :total_time=>455.71897625923157}
# stackprof --text stackprof-provider-init-broker-vmware-large-0
==================================
Mode: cpu(1000)
Samples: 362272 (3.66% miss rate)
GC: 132591 (36.60%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
34287 (9.5%) 34287 (9.5%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
15744 (4.3%) 15729 (4.3%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
14224 (3.9%) 14224 (3.9%) block in ActiveRecord::Result#hash_rows
11419 (3.2%) 11419 (3.2%) block in ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
179178 (49.5%) 10299 (2.8%) ActiveSupport::Callbacks#run_callbacks
7888 (2.2%) 7305 (2.0%) ActiveModel::AttributeMethods#respond_to?
8650 (2.4%) 5365 (1.5%) ActiveRecord::ModelSchema::ClassMethods#inheritance_column
17059 (4.7%) 4360 (1.2%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
3875 (1.1%) 3875 (1.1%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
3391 (0.9%) 3391 (0.9%) #<Module:0x007f5c77d47198>#__temp__
5986 (1.7%) 3259 (0.9%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
3155 (0.9%) 3155 (0.9%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#result_as_array
2666 (0.7%) 2666 (0.7%) Relationship#_run__137392246966907683__find__4556998815653219350__callbacks
2538 (0.7%) 2538 (0.7%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
2489 (0.7%) 2489 (0.7%) ActiveRecord::Base.logger
2363 (0.7%) 2355 (0.7%) ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods#primary_key
2312 (0.6%) 2312 (0.6%) Relationship#_run__137392246966907683__initialize__4556998815653219350__callbacks
2309 (0.6%) 2309 (0.6%) #<Module:0x007f5c6d589dc0>.enabled
2100 (0.6%) 2100 (0.6%) block in ActiveRecord::Relation#initialize
2006 (0.6%) 2006 (0.6%) ActiveRecord::Associations#association_instance_get
1959 (0.5%) 1959 (0.5%) block in ActiveRecord::Relation#initialize
2027 (0.6%) 1791 (0.5%) block in RelationshipMixin#add_children
6184 (1.7%) 1784 (0.5%) ActiveRecord::LogSubscriber#sql
1756 (0.5%) 1756 (0.5%) #<Module:0x007f5c6ebc1660>.escape_punctuation
1710 (0.5%) 1710 (0.5%) NilClass#blank?
1649 (0.5%) 1647 (0.5%) ActiveRecord::Locking::Optimistic::ClassMethods#locking_column
3917 (1.1%) 1509 (0.4%) #<Module:0x007f5c77d47198>#__temp__
1475 (0.4%) 1475 (0.4%) block (2 levels) in ActiveRecord::Base.serialized_attributes=
1441 (0.4%) 1441 (0.4%) ActiveModel::Dirty#changed_attributes
1255 (0.3%) 1255 (0.3%) String#%
vmware-large-delta with VIMBroker:
[----] I, [2015-06-07T10:08:10.775957 #41714:3f894158f3b8] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.024595022201538086, :get_vc_data=>14.434669494628906, :get_vc_data_ems_customization_specs=>3.023423671722412, :filter_vc_data=>0.00020241737365722656, :get_vc_data_host_scsi=>6.65348482131958, :get_vc_data_total=>24.137656211853027, :parse_vc_data=>10.370640993118286, :db_save_inventory=>117.8993935585022, :post_refresh_ems=>0.32627439498901367, :total_time=>152.73415350914001}
# stackprof --text stackprof-provider-delta-broker-vmware-large
==================================
Mode: cpu(1000)
Samples: 112450 (1.65% miss rate)
GC: 9565 (8.51%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
32192 (28.6%) 32192 (28.6%) ActiveRecord::ConnectionAdapters::Column.value_to_integer
7093 (6.3%) 5558 (4.9%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
4852 (4.3%) 4852 (4.3%) #<Module:0x007f1298356130>#__temp__
6585 (5.9%) 3012 (2.7%) ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
2473 (2.2%) 2473 (2.2%) ActiveRecord::Base.logger
1844 (1.6%) 1844 (1.6%) ActiveRecord::Associations#association_instance_get
1594 (1.4%) 1594 (1.4%) ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
1398 (1.2%) 1398 (1.2%) block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
1357 (1.2%) 1357 (1.2%) block (2 levels) in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute
1142 (1.0%) 1142 (1.0%) Numeric#blank?
5968 (5.3%) 1125 (1.0%) block (2 levels) in EmsRefresh::SaveInventory#save_vms_inventory
2028 (1.8%) 1031 (0.9%) ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
985 (0.9%) 985 (0.9%) String#%
14461 (12.9%) 955 (0.8%) ActiveSupport::Notifications::Instrumenter#instrument
1340 (1.2%) 930 (0.8%) MoreCoreExtensions::Shared::Nested#fetch_path
903 (0.8%) 903 (0.8%) block in ActiveRecord::Relation#initialize
875 (0.8%) 875 (0.8%) block in ActiveRecord::Relation#initialize
870 (0.8%) 870 (0.8%) ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
35613 (31.7%) 861 (0.8%) ActiveSupport::Callbacks#run_callbacks
956 (0.9%) 854 (0.8%) ActiveModel::AttributeMethods#respond_to?
1289 (1.1%) 840 (0.7%) ActiveSupport::Notifications::Event#initialize
788 (0.7%) 788 (0.7%) ActiveModel::Dirty#changed_attributes
742 (0.7%) 742 (0.7%) block (2 levels) in ActiveRecord::Base.connection_handler=
647 (0.6%) 647 (0.6%) block in ActiveRecord::Result#hash_rows
5564 (4.9%) 638 (0.6%) block in ActiveRecord::AttributeMethods#attributes
590 (0.5%) 590 (0.5%) MonitorMixin#mon_enter
560 (0.5%) 560 (0.5%) ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
1871 (1.7%) 547 (0.5%) Logger#add
528 (0.5%) 528 (0.5%) ActiveRecord::Persistence#new_record?
7065 (6.3%) 515 (0.5%) Arel::Visitors::Visitor#visit
Created attachment 1036821 [details]
Updated spreadsheet comparing CFME 5.3 (Ruby 1.9.3), CFME 5.4 (Ruby 2.0.0), and Miq (Ruby upgraded to 2.1.6)
Created attachment 1038133 [details]
Updated spreadsheet comparing CFME 5.3 (Ruby 1.9.3), CFME 5.4 (Ruby 2.0.0), and Miq (Ruby upgraded to 2.1.6)
I have retested this with an MIQ Master appliance running Ruby 2.2 and added the timing data + profiling information below. I have summarized the data in a spreadsheet that is attached as well.
# uname -a
Linux localhost.localdomain 3.10.0-229.7.2.el7.x86_64 #1 SMP Tue Jun 23 22:06:11 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
# ruby -v
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]
# rails -v
Rails 4.2.3
# cat /var/www/miq/vmdb/VERSION
master
Using the same providers and sizes as before I have witnessed decreases in % time spent in garbage collector for all tests (initial + delta refresh across all three provider sizes)
Timing data suggests that refreshes have not improved vs the ManageIQ + ruby 2.1 appliance, however there is still a significant improvement in timing data for all test cases when compared against ruby 1.93 and ruby 2.0 appliances.
vmware-small-init without VIMBroker:
[----] I, [2015-08-11T09:53:15.505839 #24376:fc998c] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1433420181274414, :get_vc_data=>2.87827467918396, :get_vc_data_ems_customization_specs=>0.0051555633544921875, :filter_vc_data=>0.0002875328063964844, :get_vc_data_host_scsi=>0.40595006942749023, :get_vc_data_total=>3.4392459392547607, :parse_vc_data=>0.5207581520080566, :db_save_inventory=>10.0387601852417, :post_refresh_ems=>0.673241138458252, :total_time=>14.672327995300293}
# stackprof --text stackprof-provider-init-vmware-small-1 --limit 10
==================================
Mode: cpu(1000)
Samples: 11331 (1.31% miss rate)
GC: 1303 (11.50%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
476 (4.2%) 324 (2.9%) ActiveRecord::LazyAttributeHash#[]
304 (2.7%) 304 (2.7%) block in MiqVimInventory#splitPropPath
284 (2.5%) 284 (2.5%) ActiveSupport::PerThreadRegistry#instance
1322 (11.7%) 236 (2.1%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
230 (2.0%) 225 (2.0%) ActiveModel::Dirty#changed_attributes
181 (1.6%) 181 (1.6%) ThreadSafe::NonConcurrentCacheBackend#[]
176 (1.6%) 176 (1.6%) ActiveRecord::Base.logger
225 (2.0%) 172 (1.5%) block (2 levels) in Class#class_attribute
162 (1.4%) 162 (1.4%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
161 (1.4%) 161 (1.4%) Nokogiri::XML::Document#decorate
vmware-small delta without VIMBroker:
[----] I, [2015-08-11T10:00:54.623392 #26478:4d998c] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.11812233924865723, :get_vc_data=>2.525672674179077, :get_vc_data_ems_customization_specs=>0.0048220157623291016, :filter_vc_data=>0.00027179718017578125, :get_vc_data_host_scsi=>0.392657995223999, :get_vc_data_total=>3.048985004425049, :parse_vc_data=>0.07587647438049316, :db_save_inventory=>4.401615619659424, :post_refresh_ems=>0.02604532241821289, :total_time=>7.552822589874268}
# stackprof --text stackprof-provider-delta-vmware-small-1 --limit 10
==================================
Mode: cpu(1000)
Samples: 5257 (1.85% miss rate)
GC: 336 (6.39%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
285 (5.4%) 285 (5.4%) block in MiqVimInventory#splitPropPath
279 (5.3%) 186 (3.5%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
282 (5.4%) 175 (3.3%) ActiveRecord::LazyAttributeHash#[]
145 (2.8%) 145 (2.8%) ActiveSupport::PerThreadRegistry#instance
142 (2.7%) 142 (2.7%) Nokogiri::XML::Document#decorate
133 (2.5%) 133 (2.5%) ThreadSafe::NonConcurrentCacheBackend#[]
117 (2.2%) 117 (2.2%) ActiveRecord::Base.logger
145 (2.8%) 114 (2.2%) block (2 levels) in Class#class_attribute
100 (1.9%) 100 (1.9%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
92 (1.8%) 92 (1.8%) ActiveRecord::Associations#association_instance_get
vmware-medium-init without VIMBroker:
[----] I, [2015-08-11T10:29:29.754382 #33148:53398c] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.13759565353393555, :get_vc_data=>20.20404815673828, :get_vc_data_ems_customization_specs=>0.01537322998046875, :filter_vc_data=>0.0002124309539794922, :get_vc_data_host_scsi=>2.266582489013672, :get_vc_data_total=>22.633290767669678, :parse_vc_data=>2.5209691524505615, :db_save_inventory=>96.7595865726471, :post_refresh_ems=>6.1543943881988525, :total_time=>128.0685956478119}
# stackprof --text stackprof-provider-init-vmware-medium-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 100848 (1.43% miss rate)
GC: 9892 (9.81%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4434 (4.4%) 4434 (4.4%) ActiveRecord::Attribute#initialize
9028 (9.0%) 4237 (4.2%) ActiveRecord::LazyAttributeHash#[]
2421 (2.4%) 2421 (2.4%) block in MiqVimInventory#splitPropPath
2405 (2.4%) 2405 (2.4%) ActiveSupport::PerThreadRegistry#instance
3315 (3.3%) 2370 (2.4%) block (2 levels) in Class#class_attribute
12498 (12.4%) 2185 (2.2%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
2116 (2.1%) 2072 (2.1%) ActiveModel::Dirty#changed_attributes
1622 (1.6%) 1622 (1.6%) ThreadSafe::NonConcurrentCacheBackend#[]
1594 (1.6%) 1594 (1.6%) block (4 levels) in Class#class_attribute
1452 (1.4%) 1452 (1.4%) ActiveRecord::Base.logger
vmware-medium-delta without VIMBroker:
[----] I, [2015-08-11T11:24:34.199177 #50155:1027988] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.15351486206054688, :get_vc_data=>20.009104251861572, :get_vc_data_ems_customization_specs=>0.004668712615966797, :filter_vc_data=>0.00025177001953125, :get_vc_data_host_scsi=>2.282381296157837, :get_vc_data_total=>22.45786190032959, :parse_vc_data=>0.6289498805999756, :db_save_inventory=>41.05992650985718, :post_refresh_ems=>0.1472470760345459, :total_time=>64.29430818557739}
# stackprof --text stackprof-provider-delta-vmware-medium-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 49818 (2.48% miss rate)
GC: 4786 (9.61%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4463 (9.0%) 3586 (7.2%) ActiveRecord::LazyAttributeHash#[]
2539 (5.1%) 2539 (5.1%) block in MiqVimInventory#splitPropPath
2823 (5.7%) 1911 (3.8%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
1483 (3.0%) 1483 (3.0%) ActiveSupport::PerThreadRegistry#instance
1361 (2.7%) 1361 (2.7%) Nokogiri::XML::Document#decorate
1091 (2.2%) 1091 (2.2%) ThreadSafe::NonConcurrentCacheBackend#[]
1009 (2.0%) 1009 (2.0%) ActiveRecord::Base.logger
905 (1.8%) 905 (1.8%) ActiveRecord::Associations#association_instance_get
846 (1.7%) 846 (1.7%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
1695 (3.4%) 838 (1.7%) ActiveRecord::Attribute#value
vmware-large-init without VIMBroker:
[----] I, [2015-08-11T11:12:56.464848 #45428:12af994] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.15024232864379883, :get_vc_data=>58.13847374916077, :get_vc_data_ems_customization_specs=>0.007879972457885742, :filter_vc_data=>0.00024366378784179688, :get_vc_data_host_scsi=>4.516143321990967, :get_vc_data_total=>62.82570815086365, :parse_vc_data=>11.992603540420532, :db_save_inventory=>419.5442683696747, :post_refresh_ems=>20.337013483047485, :total_time=>514.6999733448029}
# stackprof --text stackprof-provider-init-vmware-large-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 427177 (1.98% miss rate)
GC: 58019 (13.58%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
35422 (8.3%) 35422 (8.3%) ActiveRecord::Attribute#initialize
59600 (14.0%) 19769 (4.6%) ActiveRecord::LazyAttributeHash#[]
14256 (3.3%) 14256 (3.3%) block in ActiveRecord::Result#hash_rows
18022 (4.2%) 12833 (3.0%) block (2 levels) in Class#class_attribute
10591 (2.5%) 10591 (2.5%) ActiveRecord::Core#init_internals
7211 (1.7%) 7211 (1.7%) ActiveRecord::Type::Integer#type_cast_from_database
24621 (5.8%) 7067 (1.7%) ActiveRecord::Attribute#value
6984 (1.6%) 6984 (1.6%) ActiveSupport::PerThreadRegistry#instance
6961 (1.6%) 6961 (1.6%) block in MiqVimInventory#splitPropPath
6927 (1.6%) 6927 (1.6%) block (4 levels) in Class#class_attribute
vmware-large-delta without VIMBroker:
[----] I, [2015-08-11T11:51:16.770928 #55818:ecd998] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2212963104248047, :get_vc_data=>58.815247535705566, :get_vc_data_ems_customization_specs=>0.006624460220336914, :filter_vc_data=>0.0003612041473388672, :get_vc_data_host_scsi=>7.906996965408325, :get_vc_data_total=>66.95714950561523, :parse_vc_data=>6.243913650512695, :db_save_inventory=>144.63160109519958, :post_refresh_ems=>0.4560244083404541, :total_time=>218.28901410102844}
# stackprof --text stackprof-provider-delta-vmware-large-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 175926 (2.16% miss rate)
GC: 24837 (14.12%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
26461 (15.0%) 23858 (13.6%) ActiveRecord::LazyAttributeHash#[]
6931 (3.9%) 6931 (3.9%) block in MiqVimInventory#splitPropPath
8229 (4.7%) 5524 (3.1%) ActiveRecord::Attribute#value
7979 (4.5%) 5246 (3.0%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
3981 (2.3%) 3981 (2.3%) ActiveSupport::PerThreadRegistry#instance
3970 (2.3%) 3970 (2.3%) Nokogiri::XML::Document#decorate
2945 (1.7%) 2945 (1.7%) ThreadSafe::NonConcurrentCacheBackend#[]
2864 (1.6%) 2864 (1.6%) ActiveRecord::Base.logger
2756 (1.6%) 2756 (1.6%) ActiveRecord::Associations#association_instance_get
2513 (1.4%) 2513 (1.4%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
----------------------------------------------------------------------------------------------------------------------------------
VIMBroker
----------------------------------------------------------------------------------------------------------------------------------
vmware-small-init with VIMBroker:
[----] I, [2015-08-11T14:36:15.606227 #17140:d95990] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.09117698669433594, :get_vc_data=>0.4920542240142822, :get_vc_data_ems_customization_specs=>0.009239673614501953, :filter_vc_data=>0.0003437995910644531, :get_vc_data_host_scsi=>0.46378660202026367, :get_vc_data_total=>1.0574162006378174, :parse_vc_data=>0.5412318706512451, :db_save_inventory=>10.17768144607544, :post_refresh_ems=>0.7054078578948975, :total_time=>12.48213267326355}
# stackprof --text stackprof-provider-init-broker-vmware-small-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 10120 (0.93% miss rate)
GC: 819 (8.09%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
519 (5.1%) 366 (3.6%) ActiveRecord::LazyAttributeHash#[]
271 (2.7%) 271 (2.7%) ActiveSupport::PerThreadRegistry#instance
1337 (13.2%) 239 (2.4%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
229 (2.3%) 224 (2.2%) ActiveModel::Dirty#changed_attributes
221 (2.2%) 221 (2.2%) ThreadSafe::NonConcurrentCacheBackend#[]
236 (2.3%) 170 (1.7%) block (2 levels) in Class#class_attribute
164 (1.6%) 164 (1.6%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
159 (1.6%) 159 (1.6%) ActiveRecord::Attribute#initialize
140 (1.4%) 140 (1.4%) ActiveRecord::Base.logger
139 (1.4%) 139 (1.4%) block (4 levels) in Class#class_attribute
vmware-small-delta with VIMBroker:
[----] I, [2015-08-11T15:54:04.991534 #54411:ff9998] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.014748096466064453, :get_vc_data=>0.4799377918243408, :get_vc_data_ems_customization_specs=>0.009073495864868164, :filter_vc_data=>0.0002551078796386719, :get_vc_data_host_scsi=>0.44733524322509766, :get_vc_data_total=>0.9522278308868408, :parse_vc_data=>0.10468316078186035, :db_save_inventory=>4.411359071731567, :post_refresh_ems=>0.02493429183959961, :total_time=>5.493463039398193}
# stackprof --text stackprof-provider-delta-broker-vmware-small-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 4630 (1.34% miss rate)
GC: 145 (3.13%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
380 (8.2%) 256 (5.5%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
305 (6.6%) 197 (4.3%) ActiveRecord::LazyAttributeHash#[]
166 (3.6%) 166 (3.6%) ActiveSupport::PerThreadRegistry#instance
135 (2.9%) 135 (2.9%) ThreadSafe::NonConcurrentCacheBackend#[]
114 (2.5%) 114 (2.5%) ActiveRecord::Base.logger
152 (3.3%) 112 (2.4%) block (2 levels) in Class#class_attribute
106 (2.3%) 106 (2.3%) ActiveRecord::Associations#association_instance_get
93 (2.0%) 93 (2.0%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
88 (1.9%) 88 (1.9%) ActiveRecord::Attribute#initialize
83 (1.8%) 83 (1.8%) ActiveRecord::ConnectionAdapters::TransactionState#finalized?
vmware-medium-init with VIMBroker:
[----] I, [2015-08-11T15:02:08.168644 #23245:dcb98c] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.09477806091308594, :get_vc_data=>4.338020324707031, :get_vc_data_ems_customization_specs=>0.01003575325012207, :filter_vc_data=>0.00029277801513671875, :get_vc_data_host_scsi=>2.4946229457855225, :get_vc_data_total=>6.938694000244141, :parse_vc_data=>2.3875858783721924, :db_save_inventory=>98.44503045082092, :post_refresh_ems=>6.666780710220337, :total_time=>114.43852734565735}
# stackprof --text stackprof-provider-init-broker-vmware-medium-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 93127 (1.00% miss rate)
GC: 9116 (9.79%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4490 (4.8%) 4490 (4.8%) ActiveRecord::Attribute#initialize
8986 (9.6%) 4164 (4.5%) ActiveRecord::LazyAttributeHash#[]
3282 (3.5%) 2443 (2.6%) block (2 levels) in Class#class_attribute
2348 (2.5%) 2348 (2.5%) ActiveSupport::PerThreadRegistry#instance
12563 (13.5%) 2125 (2.3%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
2151 (2.3%) 2113 (2.3%) ActiveModel::Dirty#changed_attributes
1635 (1.8%) 1635 (1.8%) ThreadSafe::NonConcurrentCacheBackend#[]
1500 (1.6%) 1500 (1.6%) ActiveRecord::Base.logger
1486 (1.6%) 1486 (1.6%) block (4 levels) in Class#class_attribute
1448 (1.6%) 1448 (1.6%) block in ActiveRecord::Result#hash_rows
vmware-medium-delta with VIMBroker:
[----] I, [2015-08-11T16:05:56.221717 #56221:d37994] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-medium], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.03416872024536133, :get_vc_data=>5.807108402252197, :get_vc_data_ems_customization_specs=>0.00922703742980957, :filter_vc_data=>0.0003466606140136719, :get_vc_data_host_scsi=>2.576259136199951, :get_vc_data_total=>8.428082942962646, :parse_vc_data=>0.6040685176849365, :db_save_inventory=>41.992419958114624, :post_refresh_ems=>0.15120506286621094, :total_time=>51.17606568336487}
# stackprof --text stackprof-provider-delta-broker-vmware-medium-2 --limit 10
==================================
Mode: cpu(1000)
Samples: 40408 (1.20% miss rate)
GC: 2436 (6.03%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
4734 (11.7%) 3866 (9.6%) ActiveRecord::LazyAttributeHash#[]
2661 (6.6%) 1770 (4.4%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
1446 (3.6%) 1446 (3.6%) ActiveSupport::PerThreadRegistry#instance
1102 (2.7%) 1102 (2.7%) ActiveRecord::Base.logger
1869 (4.6%) 964 (2.4%) ActiveRecord::Attribute#value
957 (2.4%) 957 (2.4%) ThreadSafe::NonConcurrentCacheBackend#[]
1193 (3.0%) 835 (2.1%) block (2 levels) in Class#class_attribute
831 (2.1%) 831 (2.1%) ActiveRecord::Associations#association_instance_get
821 (2.0%) 821 (2.0%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
780 (1.9%) 780 (1.9%) ActiveRecord::Attribute#initialize
vmware-large-init with VIMBroker:
[----] I, [2015-08-11T15:32:16.044245 #48047:79b990] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.09881258010864258, :get_vc_data=>13.50426173210144, :get_vc_data_ems_customization_specs=>0.010170221328735352, :filter_vc_data=>0.00045037269592285156, :get_vc_data_host_scsi=>8.951781511306763, :get_vc_data_total=>22.566840171813965, :parse_vc_data=>14.949150562286377, :db_save_inventory=>420.31304907798767, :post_refresh_ems=>19.969604969024658, :total_time=>477.79905366897583}
# stackprof --text stackprof-provider-init-broker-vmware-large-1 --limit 10
==================================
Mode: cpu(1000)
Samples: 390575 (1.47% miss rate)
GC: 55965 (14.33%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
34032 (8.7%) 34032 (8.7%) ActiveRecord::Attribute#initialize
57489 (14.7%) 19548 (5.0%) ActiveRecord::LazyAttributeHash#[]
12630 (3.2%) 12630 (3.2%) block in ActiveRecord::Result#hash_rows
17104 (4.4%) 12406 (3.2%) block (2 levels) in Class#class_attribute
9807 (2.5%) 9807 (2.5%) ActiveRecord::Core#init_internals
7834 (2.0%) 7834 (2.0%) ActiveRecord::Type::Integer#type_cast_from_database
25302 (6.5%) 7344 (1.9%) ActiveRecord::Attribute#value
6882 (1.8%) 6882 (1.8%) ActiveSupport::PerThreadRegistry#instance
6600 (1.7%) 6600 (1.7%) block (4 levels) in Class#class_attribute
36487 (9.3%) 6505 (1.7%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
vmware-large-delta with VIMBroker:
[----] I, [2015-08-11T16:27:26.702464 #61195:8a5994] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) EMS: [vmware-large], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.029696941375732422, :get_vc_data=>14.29965877532959, :get_vc_data_ems_customization_specs=>0.02301311492919922, :filter_vc_data=>0.00043511390686035156, :get_vc_data_host_scsi=>5.646241903305054, :get_vc_data_total=>20.000197172164917, :parse_vc_data=>4.64498233795166, :db_save_inventory=>156.96665906906128, :post_refresh_ems=>0.5521109104156494, :total_time=>182.16430687904358}
# stackprof --text stackprof-provider-delta-broker-vmware-large-1 --limit 10
==================================
Mode: cpu(1000)
Samples: 151731 (1.05% miss rate)
GC: 9921 (6.54%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
31453 (20.7%) 28728 (18.9%) ActiveRecord::LazyAttributeHash#[]
10311 (6.8%) 7563 (5.0%) ActiveRecord::Attribute#value
9275 (6.1%) 6172 (4.1%) block in ActiveRecord::AutosaveAssociation::ClassMethods#define_non_cyclic_method
4344 (2.9%) 4344 (2.9%) ActiveSupport::PerThreadRegistry#instance
3052 (2.0%) 3052 (2.0%) ActiveRecord::Associations#association_instance_get
3014 (2.0%) 3014 (2.0%) ThreadSafe::NonConcurrentCacheBackend#[]
3003 (2.0%) 3003 (2.0%) ActiveRecord::Base.logger
3897 (2.6%) 2768 (1.8%) block (2 levels) in Class#class_attribute
2533 (1.7%) 2533 (1.7%) ThreadSafe::NonConcurrentCacheBackend#get_or_default
2390 (1.6%) 2390 (1.6%) ActiveRecord::Attribute#initialize
Created attachment 1061720 [details]
Ruby 1.9.3,2.0.0,2.1,2.2.2 on CFME/ManageIQ Refresh Timings
Awesome Alex! Note, it's important to keep in mind that Rails 4+ includes many performance improvements and may also have other changes could affect refresh timings/garbage collection results. Your ruby 2.2.2 and 2.1.6 results are probably getting some benefits of a newer Rails 4+ over your prior results. It's hard to normalize these results since environmental changes could also at play here but in general, we'd expect much less time in GC at the expense of more memory usage at most samples. It might be useful to track memory usage too. This is great information! Thanks! Joe, You are absolutely right there are many variables at play between each of the compared timings and % time spent in garbage collector. Code changes, Ruby version, RHEL/Centos version, etc. I don't have numbers around the memory usage per refresh operation but I will research capturing that data into these benchmarks in the future as well. I do expect that the architecture changes in the Garbage collector from 1.9.3 up to Ruby 2.2 would show some reduced memory usage with bitmap marking and incremental GC with RIncGC in Ruby 2.2. The environments tested are static so they should not change the refresh timings much if any but simply the changes in the appliances themselves. Additionally, the virtualization environment could introduce some variance, though controls have been taken to reduce that variance. Given all the recent code changes regarding memory utilization, plus the updated Ruby & Rails versions, can we get date for either Master or 5.5? Time spent in garbage collection has is now about 1/4 or less of the time previously spent in garbage collection. This ticket is being closed as we have met the goal of this ticket (reduction in garbage collection time), additionally efforts to reduce the time spent performing garbage collection will continue as part of regular performance work. I don't see actual PR to test against. Given Alex's comment showing some improvement, I'm moving this to Verified. We can reopen it again if additional data warrants that. Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2016:1348 |
Description of problem: Profiling EmsRefresh attached to VMware providers of different sizes shows a large amount of time spent in the garbage collector. Small - 100 Vms Medium - 1k Vms Large - 3k Vms Initial Refresh - First refresh after attaching an environment Without VIMBroker: Small --- Large 45.4% - 37.6% of samples spent in the garbage_collector with VIMBroker: 45.9% - 64.3% of samples spent in the garbage collector Delta Refresh - subsequent refreshes after initial refresh Without VIMBroker: 33.7% - 44.3% of samples spent in the garbage_collector with VIMBroker: 27% - 58.6% of samples spent in the garbage_collector Reducing the amount of time spent in the garbage collector can provide for faster refreshes. Actual data: vmware-small-init without VIMBroker: [----] I, [2015-04-07T17:57:33.719892 #10813:9ab80c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.3016831874847412, :get_vc_data=>2.9035086631774902, :get_vc_data_ems_customization_specs=>0.006135702133178711, :filter_vc_data=>0.000244140625, :get_vc_data_host_scsi=>0.4829566478729248, :get_vc_data_total=>3.701056718826294, :parse_vc_data=>18.55411458015442, :db_save_inventory=>10.302927017211914, :post_refresh_ems=>0.9918920993804932, :total_time=>33.550310373306274} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-small-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-small-1. Total: 1566 samples 711 45.4% 45.4% 711 45.4% garbage_collector 71 4.5% 49.9% 841 53.7% Kernel#require 29 1.9% 51.8% 31 2.0% Module#module_eval 26 1.7% 53.4% 42 2.7% Module#class_eval 17 1.1% 54.5% 17 1.1% String#split 16 1.0% 55.6% 16 1.0% Kernel#respond_to? 12 0.8% 56.3% 12 0.8% Kernel#kind_of? 12 0.8% 57.1% 12 0.8% Module#method_defined? 11 0.7% 57.8% 11 0.7% Enumerable#any? vmware-small delta without VIMBroker: [----] I, [2015-04-07T18:07:48.936513 #10813:9ab80c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.12036371231079102, :get_vc_data=>3.111366033554077, :get_vc_data_ems_customization_specs=>0.004431009292602539, :filter_vc_data=>0.00026726722717285156, :get_vc_data_host_scsi=>0.6039416790008545, :get_vc_data_total=>3.8483550548553467, :parse_vc_data=>1.0214672088623047, :db_save_inventory=>3.9047677516937256, :post_refresh_ems=>0.019001245498657227, :total_time=>8.793952941894531} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-small-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-small-1. Total: 593 samples 200 33.7% 33.7% 200 33.7% garbage_collector 21 3.5% 37.3% 21 3.5% String#split 12 2.0% 39.3% 39 6.6% MiqVimInventory#splitPropPath 12 2.0% 41.3% 45 7.6% VimService#unmarshal_response 8 1.3% 42.7% 8 1.3% Array#hash 8 1.3% 44.0% 8 1.3% Kernel#kind_of? 8 1.3% 45.4% 8 1.3% PGconn#async_exec 7 1.2% 46.5% 28 4.7% Hash#bracket_equals_with_subclassed_string 7 1.2% 47.7% 10 1.7% Nokogiri::XML::Node#children vmware-medium-init without VIMBroker: [----] I, [2015-04-07T18:14:16.702102 #11900:11fe810] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [2] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2976875305175781, :get_vc_data=>22.890995979309082, :get_vc_data_ems_customization_specs=>0.014676094055175781, :filter_vc_data=>0.0003101825714111328, :get_vc_data_host_scsi=>3.267127752304077, :get_vc_data_total=>26.478687286376953, :parse_vc_data=>23.072560787200928, :db_save_inventory=>99.13876676559448, :post_refresh_ems=>6.883234739303589, :total_time=>155.5736072063446} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-medium-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-medium-1. Total: 12159 samples 4620 38.0% 38.0% 4620 38.0% garbage_collector 199 1.6% 39.6% 528 4.3% ActiveRecord::AttributeMethods#respond_to? 187 1.5% 41.2% 187 1.5% String#split 173 1.4% 42.6% 285 2.3% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name 169 1.4% 44.0% 325 2.7% #<Module:0x00000006ba5418>#__temp__ 142 1.2% 45.2% 2389 19.6% ActiveSupport::Callbacks#run_callbacks 134 1.1% 46.3% 241 2.0% ActiveModel::AttributeMethods#respond_to? 128 1.1% 47.3% 128 1.1% PGconn#async_exec 123 1.0% 48.3% 126 1.0% Kernel#respond_to? vmware-medium-delta without VIMBroker: [----] I, [2015-04-07T18:18:45.996855 #11900:11fe810] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [2] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.14052510261535645, :get_vc_data=>28.685588836669922, :get_vc_data_ems_customization_specs=>0.007360696792602539, :filter_vc_data=>0.00027561187744140625, :get_vc_data_host_scsi=>3.340131998062134, :get_vc_data_total=>32.182886362075806, :parse_vc_data=>4.922174692153931, :db_save_inventory=>43.459251403808594, :post_refresh_ems=>0.11832714080810547, :total_time=>80.68297457695007} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-medium-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-medium-1. Total: 6432 samples 2410 37.5% 37.5% 2410 37.5% garbage_collector 179 2.8% 40.3% 312 4.9% #<Module:0x00000008471960>#__temp__ 157 2.4% 42.7% 157 2.4% String#split 107 1.7% 44.4% 107 1.7% PGconn#async_exec 105 1.6% 46.0% 390 6.1% ActiveRecord::Base#== 104 1.6% 47.6% 448 7.0% VimService#unmarshal_response 96 1.5% 49.1% 128 2.0% Nokogiri::XML::Node#children 83 1.3% 50.4% 88 1.4% Array#hash 80 1.2% 51.6% 80 1.2% Module#=== vmware-large-init without VIMBroker: [----] I, [2015-04-07T19:28:00.762039 #43694:a2a814] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [3] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.28109192848205566, :get_vc_data=>61.35445523262024, :get_vc_data_ems_customization_specs=>0.006406068801879883, :filter_vc_data=>0.00030994415283203125, :get_vc_data_host_scsi=>6.5239763259887695, :get_vc_data_total=>68.17294549942017, :parse_vc_data=>31.65355396270752, :db_save_inventory=>511.353791475296, :post_refresh_ems=>19.521234035491943, :total_time=>630.701917886734} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-large-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-large-1. Total: 55961 samples 21033 37.6% 37.6% 21033 37.6% garbage_collector 1622 2.9% 40.5% 3138 5.6% #<Module:0x000000069e58a8>#__temp__ 1467 2.6% 43.1% 3384 6.0% ActiveRecord::AttributeMethods#respond_to? 1397 2.5% 45.6% 2505 4.5% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name 1092 2.0% 47.6% 1663 3.0% ActiveModel::AttributeMethods#respond_to? 998 1.8% 49.3% 11274 20.1% ActiveSupport::Callbacks#run_callbacks 908 1.6% 51.0% 909 1.6% Hash.[] 883 1.6% 52.5% 10294 18.4% ActiveRecord::Inheritance::ClassMethods#instantiate 809 1.4% 54.0% 809 1.4% Module#=== vmware-large-delta without VIMBroker: [----] I, [2015-04-07T19:34:01.702711 #43694:a2a814] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [3] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.1942586898803711, :get_vc_data=>86.56293511390686, :get_vc_data_ems_customization_specs=>0.007265567779541016, :filter_vc_data=>0.0003063678741455078, :get_vc_data_host_scsi=>7.850905418395996, :get_vc_data_total=>94.62202978134155, :parse_vc_data=>6.120851755142212, :db_save_inventory=>189.55883193016052, :post_refresh_ems=>0.37494707107543945, :total_time=>290.6777756214142} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-large-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-large-1. Total: 25754 samples 11400 44.3% 44.3% 11400 44.3% garbage_collector 1344 5.2% 49.5% 2451 9.5% #<Module:0x00000007a38480>#__temp__ 925 3.6% 53.1% 3155 12.3% ActiveRecord::Base#== 560 2.2% 55.2% 560 2.2% Module#=== 502 1.9% 57.2% 502 1.9% String#split 327 1.3% 58.5% 327 1.3% PGconn#async_exec 291 1.1% 59.6% 389 1.5% Nokogiri::XML::Node#children 285 1.1% 60.7% 285 1.1% Hash#has_key? 279 1.1% 61.8% 1337 5.2% VimService#unmarshal_response ---------------------------------------------------------------------------------------------------------------------------------- VIMBroker ---------------------------------------------------------------------------------------------------------------------------------- vmware-small-init with VIMBroker: [----] I, [2015-04-07T18:32:27.590662 #37729:8ed014] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2770664691925049, :get_vc_data=>0.49970507621765137, :get_vc_data_ems_customization_specs=>0.008992433547973633, :filter_vc_data=>0.0003037452697753906, :get_vc_data_host_scsi=>1.324699878692627, :get_vc_data_total=>2.1116902828216553, :parse_vc_data=>0.4445176124572754, :db_save_inventory=>9.9948091506958, :post_refresh_ems=>1.068671703338623, :total_time=>13.620014905929565} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-small-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-small-VIMBroker-1. Total: 1400 samples 643 45.9% 45.9% 643 45.9% garbage_collector 74 5.3% 51.2% 741 52.9% Kernel#require 21 1.5% 52.7% 21 1.5% Module#module_eval 18 1.3% 54.0% 40 2.9% Module#class_eval 16 1.1% 55.1% 16 1.1% Module#method_defined? 14 1.0% 56.1% 14 1.0% Kernel#respond_to? 14 1.0% 57.1% 14 1.0% PGconn#async_exec 11 0.8% 57.9% 20 1.4% Hash#bracket_equals_without_subclassed_string 10 0.7% 58.6% 18 1.3% ActiveRecord::AttributeMethods::ClassMethods#method_defined_within? vmware-small-delta with VIMBroker: [----] I, [2015-04-07T18:33:38.119541 #37729:8ed014] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-small], id: [1] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.02829289436340332, :get_vc_data=>0.44432926177978516, :get_vc_data_ems_customization_specs=>0.009057998657226562, :filter_vc_data=>0.0003077983856201172, :get_vc_data_host_scsi=>1.3963871002197266, :get_vc_data_total=>1.8812754154205322, :parse_vc_data=>0.18120789527893066, :db_save_inventory=>4.006829738616943, :post_refresh_ems=>0.019440412521362305, :total_time=>6.089089632034302} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-small-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-small-VIMBroker-1. Total: 396 samples 107 27.0% 27.0% 107 27.0% garbage_collector 8 2.0% 29.0% 8 2.0% Array#hash 7 1.8% 30.8% 25 6.3% ActiveRecord::AttributeMethods::Read#read_attribute 7 1.8% 32.6% 18 4.5% ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute 7 1.8% 34.3% 7 1.8% Class#logger 7 1.8% 36.1% 14 3.5% Hash#bracket_equals_without_subclassed_string 7 1.8% 37.9% 7 1.8% PGconn#async_exec 6 1.5% 39.4% 6 1.5% Marshal.load_without_autoload_missing_constants 6 1.5% 40.9% 6 1.5% Module#method_defined? vmware-medium-init with VIMBroker: [----] I, [2015-04-07T18:38:35.305003 #38141:f7d80c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [2] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2805607318878174, :get_vc_data=>6.464196443557739, :get_vc_data_ems_customization_specs=>0.017713546752929688, :filter_vc_data=>0.00025582313537597656, :get_vc_data_host_scsi=>4.056087017059326, :get_vc_data_total=>10.819653987884521, :parse_vc_data=>3.3389196395874023, :db_save_inventory=>124.64521813392639, :post_refresh_ems=>9.491732597351074, :total_time=>148.29584670066833} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-medium-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-medium-VIMBroker-1. Total: 13345 samples 6861 51.4% 51.4% 6861 51.4% garbage_collector 210 1.6% 53.0% 548 4.1% ActiveRecord::AttributeMethods#respond_to? 159 1.2% 54.2% 265 2.0% ActiveModel::AttributeMethods#respond_to? 154 1.2% 55.3% 317 2.4% #<Module:0x0000000821c4a8>#__temp__ 152 1.1% 56.5% 152 1.1% PGconn#async_exec 143 1.1% 57.5% 274 2.1% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name 136 1.0% 58.6% 2364 17.7% ActiveSupport::Callbacks#run_callbacks 114 0.9% 59.4% 115 0.9% Kernel#respond_to? 109 0.8% 60.2% 109 0.8% Hash.[] vmware-medium-delta with VIMBroker: [----] I, [2015-04-07T18:40:44.709712 #38141:f7d80c] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-medium], id: [2] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.02484917640686035, :get_vc_data=>8.361079454421997, :get_vc_data_ems_customization_specs=>0.0085906982421875, :filter_vc_data=>0.0003056526184082031, :get_vc_data_host_scsi=>4.056894063949585, :get_vc_data_total=>12.452688932418823, :parse_vc_data=>2.901001453399658, :db_save_inventory=>58.77647805213928, :post_refresh_ems=>0.12518596649169922, :total_time=>74.25564742088318} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-medium-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-medium-VIMBroker-1. Total: 6074 samples 3056 50.3% 50.3% 3056 50.3% garbage_collector 185 3.0% 53.4% 305 5.0% #<Module:0x00000007e46b80>#__temp__ 124 2.0% 55.4% 406 6.7% ActiveRecord::Base#== 104 1.7% 57.1% 104 1.7% PGconn#async_exec 77 1.3% 58.4% 77 1.3% Module#=== 70 1.2% 59.5% 197 3.2% ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute 67 1.1% 60.6% 70 1.2% Array#hash 56 0.9% 61.6% 57 0.9% Marshal.load_without_autoload_missing_constants 52 0.9% 62.4% 98 1.6% ActiveRecord::AttributeMethods#respond_to? vmware-large-init with VIMBroker: [----] I, [2015-04-07T19:01:09.973013 #39253:e04804] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [3] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.2801980972290039, :get_vc_data=>20.290126085281372, :get_vc_data_ems_customization_specs=>0.017542123794555664, :filter_vc_data=>0.00029587745666503906, :get_vc_data_host_scsi=>8.133896589279175, :get_vc_data_total=>28.722965240478516, :parse_vc_data=>42.76042604446411, :db_save_inventory=>843.4962222576141, :post_refresh_ems=>35.005037784576416, :total_time=>949.9849474430084} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_init-vmware-large-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_init-vmware-large-VIMBroker-1. Total: 86301 samples 55531 64.3% 64.3% 55531 64.3% garbage_collector 1609 1.9% 66.2% 3271 3.8% #<Module:0x00000008ca7378>#__temp__ 1496 1.7% 67.9% 3288 3.8% ActiveRecord::AttributeMethods#respond_to? 1382 1.6% 69.5% 2464 2.9% ActiveSupport::Callbacks::ClassMethods#__callback_runner_name 1036 1.2% 70.7% 11270 13.1% ActiveSupport::Callbacks#run_callbacks 939 1.1% 71.8% 1490 1.7% ActiveModel::AttributeMethods#respond_to? 894 1.0% 72.9% 896 1.0% Hash.[] 859 1.0% 73.9% 859 1.0% Module#=== 854 1.0% 74.9% 10207 11.8% ActiveRecord::Inheritance::ClassMethods#instantiate vmware-large-delta with VIMBroker: [----] I, [2015-04-07T19:09:02.475517 #39253:e04804] INFO -- : MIQ(VcRefresher.refresh) EMS: [vmware-large], id: [3] Refreshing targets for EMS...Complete - Timings: {:get_ems_data=>0.041292428970336914, :get_vc_data=>25.786489009857178, :get_vc_data_ems_customization_specs=>0.018430233001708984, :filter_vc_data=>0.00031685829162597656, :get_vc_data_host_scsi=>8.167120218276978, :get_vc_data_total=>34.01460576057434, :parse_vc_data=>31.887337923049927, :db_save_inventory=>259.28945326805115, :post_refresh_ems=>0.38197779655456543, :total_time=>325.57371068000793} # /opt/rh/ruby193/root/usr/local/share/gems/gems/perftools.rb-2.0.1/bin/pprof.rb profile-ems_refresh_delta-vmware-large-VIMBroker-1 | head Using local file /opt/rh/ruby193/root/usr/bin/ruby. Using local file profile-ems_refresh_delta-vmware-large-VIMBroker-1. Total: 26968 samples 15815 58.6% 58.6% 15815 58.6% garbage_collector 1213 4.5% 63.1% 2420 9.0% #<Module:0x000000083a95f0>#__temp__ 966 3.6% 66.7% 3287 12.2% ActiveRecord::Base#== 725 2.7% 69.4% 725 2.7% Module#=== 302 1.1% 70.5% 1177 4.4% Class#value_to_integer 275 1.0% 71.6% 275 1.0% PGconn#async_exec 188 0.7% 72.2% 194 0.7% Array#hash 184 0.7% 72.9% 558 2.1% ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute 181 0.7% 73.6% 181 0.7% String#to_i