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
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