Skip to content

Instantly share code, notes, and snippets.

@NickLaMuro

NickLaMuro/README.md Secret

Last active November 11, 2020 00:10
Show Gist options
  • Star 2 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save NickLaMuro/36f9f394a5b3cecc4aaf33d3e84dfb27 to your computer and use it in GitHub Desktop.
Save NickLaMuro/36f9f394a5b3cecc4aaf33d3e84dfb27 to your computer and use it in GitHub Desktop.
Download ZIP
MiqRequestWorkflow optimizations document
Raw
README.md

This document is meant to serve as an overall before/after of the changes to MiqRequestWorkflow for performance optmizations. This combines the efforts found in the following pull requests:

Or the combined branch, which is meant to encompass all of the above:

https://github.com/ManageIQ/manageiq/compare/master...NickLaMuro:multiple_miq_provision_workflow_query_optimizations

and will be a ever change branch more fixes are added or the above are edited.

Note: Changes in provider repos are not reflected in the above branch, but are brought in by pointing to local copies of the gems by using bundler.d/Gemfile.dev.rb.

Optimization Results

The benchmark script used here basically runs the following:

ManageIQ::Providers::Vmware::InfraManager::ProvisionWorkflow.new.init_from_dialog

And is targeting a fairly large EMS, with about 600 hosts. A sample script that was used to take these benchmark numbers is also provided below.

Timings and Queries

The initial effort to reduce the N+1 queries in this action was done in ManageIQ/manageiq#17354, but as noted in the later CPU usage section, there is a substancial amount of time spent in garbage collection, so reducing the N+1 queries was only a small reduction in the overall time taken.

Further improvements on reducing the number of rows however (in ManageIQ/manageiq#17381 and related PRs) helped significantly on a number of fronts.

ms queries query (ms) rows
before 15023 1961 715.2 48395
after 1604 48 205.7 15107

Allocated Objects

Note: The change might be hard to see in the totals, but it is a decrease by OVER a factor of 10.

Before                                                     After
------                                                     -----

Total allocated: 2069091751 bytes (23226536 objects)   |   Total allocated: 109447337 bytes (1062611 objects)
                                                       |   
allocated objects by gem                               |   allocated objects by gem
-----------------------------------                    |   -----------------------------------
   9665227  pending                                    |       525091  activerecord-5.0.7
   5561668  manageiq/app                               |       167427  activemodel-5.0.7
   3513258  manageiq/lib                               |        82799  pending
   2512007  activerecord-5.0.7                         |        73243  ruby-2.3.3/lib
    861270  activesupport-5.0.7                        |        67753  activesupport-5.0.7
    418737  ancestry-2.2.2                             |        59319  manageiq/app
    278793  activemodel-5.0.7                          |        35578  ancestry-2.2.2
    178419  ruby-2.3.3/lib                             |        25320  arel-7.1.4
    165577  arel-7.1.4                                 |        13032  fast_gettext-1.2.0
     52875  manageiq-providers-vmware-0be2f13a0dc9     |        12295  manageiq/lib
     14424  fast_gettext-1.2.0                         |          318  manageiq-providers-vmware-0be2f13a0dc9
      4115  other                                      |          283  other
        75  default_value_for-3.0.5                    |           75  default_value_for-3.0.5
        68  concurrent-ruby-1.0.5                      |           58  concurrent-ruby-1.0.5
        16  memoist-0.15.0                             |           16  memoist-0.15.0
         4  rubygems                                   |            4  rubygems

CPU Usage

A big note here is the amount of time spent in "(garbage collection)", and since there are a lot of throw away objects being created, this has a substancial impact on the time speant in this request.

Before

==================================
  Mode: wall(1000)
  Samples: 15664 (1.10% miss rate)
  GC: 5275 (33.68%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      5275  (33.7%)        5275  (33.7%)     (garbage collection)
      1808  (11.5%)        1808  (11.5%)     MiqHashStruct#method_missing
      1310   (8.4%)        1310   (8.4%)     Vmdb::LogProxy#prefix
      1599  (10.2%)         587   (3.7%)     MiqRequestWorkflow#load_ems_node
       597   (3.8%)         476   (3.0%)     ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
       365   (2.3%)         365   (2.3%)     ActiveSupport::NumericWithFormat#to_s
       297   (1.9%)         297   (1.9%)     XmlHash::Element#attributes
       266   (1.7%)         266   (1.7%)     ActiveRecord::Attribute#initialize
       358   (2.3%)         248   (1.6%)     ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
       243   (1.6%)         243   (1.6%)     ActiveRecord::Result#hash_rows
       536   (3.4%)         228   (1.5%)     ActiveRecord::LazyAttributeHash#[]
       180   (1.1%)         180   (1.1%)     XmlHash::Attributes#[]
       177   (1.1%)         177   (1.1%)     Vmdb::ClassLogging#instance_logger
       148   (0.9%)         148   (0.9%)     String#blank?
       145   (0.9%)         145   (0.9%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
       110   (0.7%)         110   (0.7%)     ActiveRecord::ModelSchema::ClassMethods#inheritance_column
        90   (0.6%)          90   (0.6%)     block (4 levels) in class_attribute
        85   (0.5%)          85   (0.5%)     ActiveRecord::Core#init_internals
        84   (0.5%)          84   (0.5%)     #<Module:0x007faccbcb4f38>.accumulate_descendants
        78   (0.5%)          78   (0.5%)     ActiveRecord::Base.logger

After

==================================
  Mode: wall(1000)
  Samples: 1583 (1.25% miss rate)
  GC: 173 (10.93%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       213  (13.5%)         203  (12.8%)     ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
       173  (10.9%)         173  (10.9%)     (garbage collection)
       133   (8.4%)         133   (8.4%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
        70   (4.4%)          70   (4.4%)     ActiveRecord::Result#hash_rows
        61   (3.9%)          61   (3.9%)     ActiveRecord::Attribute#initialize
       121   (7.6%)          51   (3.2%)     ActiveRecord::LazyAttributeHash#[]
        41   (2.6%)          41   (2.6%)     ActiveRecord::ModelSchema::ClassMethods#inheritance_column
        27   (1.7%)          27   (1.7%)     ActiveRecord::AttributeMethods::ClassMethods#method_defined_within?
        26   (1.6%)          26   (1.6%)     Relationship#ancestry_base_class
        24   (1.5%)          24   (1.5%)     OpenStruct#new_ostruct_member
        26   (1.6%)          23   (1.5%)     ActiveSupport::Inflector#underscore
        22   (1.4%)          22   (1.4%)     Relationship.ancestry_column
        20   (1.3%)          20   (1.3%)     ActiveRecord::AttributeMethods::Write::ClassMethods#define_method_attribute=
        20   (1.3%)          20   (1.3%)     ActiveRecord::Core#init_internals
        19   (1.2%)          19   (1.2%)     ActiveModel::Type::String#cast_value
        16   (1.0%)          16   (1.0%)     #<Module:0x007fa4a1c9a480>.convert
        36   (2.3%)          16   (1.0%)     XmlHash::Element#each_element
        15   (0.9%)          15   (0.9%)     #<Module:0x007fa4a208f838>.accumulate_descendants
        39   (2.5%)          15   (0.9%)     OpenStruct#method_missing
        15   (0.9%)          15   (0.9%)     block (4 levels) in class_attribute
Raw
sample_profile_script.rb
# The following script should be run with rails runner:
#
# $ bin/rails runner [NAME_OF_THIS_SCRIPT].rb
#
# Variables to tweak for your environment (can stay as strings)
vm_id = "[INSERT_VM_ID_TO_CLONE_ID_HERE]"
vm_name = "[INSERT_NAME_OF_VM_CLONE_ID_HERE]"
user_id = "[INSERT_USER_ID_HERE]"
current_user = User.find(user_id.to_i)
new_options = {
:src_vm_id => vm_id,
:request_type => :clone_to_template
}
dialog_options = {
:src_vm_id => [vm_id.to_i, vm_name],
:request_type => :clone_to_template,
:miq_request_dialog_name => "miq_provision_vmware_dialogs_clone_to_template",
:customize_enabled => ["disabled"],
:current_tab_key => :requester
}
workflow = ManageIQ::Providers::Vmware::InfraManager::ProvisionWorkflow.new({}, current_user, new_options)
# Profiling wrapped around this line...
workflow.init_from_dialog dialog_options
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment