Make Benchmark Timing output more sensible

The current Benchmark timings do a good job of capturing the time it took to do various blocks, but one of the things that it's missing is the ability to group, or nest, timings the same way we're nesting the calls to Benchmark.realtime_block in the code.

For instance, in the VMWare EMS Refresh process, we have several calls to Benchmark.realtime_block. If I grouped the timing keys together to represent their call stack, it would look like:

- ems_refresh
| - collect_inventory_for_targets
  | - get_ems_data
  | - get_vc_data
  | - get_vc_data_ems_customization_specs (optional)
  | - filter_vc_data
  | - get_vc_data_host_scsi
| - parse_targeted_inventory
  | - parse_vc_data
| - save_inventory
  | - db_save_inventory

However, this is what we currently output when we capture the Benchmark.realtime_block:

[----] I, [2016-09-25T20:29:39.651349 #30193:ea3990] INFO -- : 
MIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) 
EMS: [EMS NAME], id: [50000000000004] Refreshing targets for EMS...Complete - 
Timings {:server_dequeue=>0.0058367252349853516, :get_ems_data=>9.814793109893799, 
:get_vc_data=>89.20815706253052, :filter_vc_data=>0.020371675491333008, 
:get_vc_data_host_scsi=>16.73558282852173, 
:collect_inventory_for_targets=>115.83132314682007, :parse_vc_data=>0.729074239730835, 
:parse_targeted_inventory=>0.729581356048584, :db_save_inventory=>32.98734211921692, 
:save_inventory=>32.98742628097534, :ems_refresh=>149.55086016654968}

If I scale that back to just the hash of timings, it looks like (newlines and formatting added):

{
 :server_dequeue                => 0.0058367252349853516, 
 :get_ems_data                  => 9.814793109893799, 
 :get_vc_data                   => 89.20815706253052, 
 :filter_vc_data                => 0.020371675491333008, 
 :get_vc_data_host_scsi         => 16.73558282852173, 
 :collect_inventory_for_targets => 115.83132314682007, 
 :parse_vc_data                 => 0.729074239730835, 
 :parse_targeted_inventory      => 0.729581356048584, 
 :db_save_inventory             => 32.98734211921692, 
 :save_inventory                => 32.98742628097534, 
 :ems_refresh                   => 149.55086016654968
}

There's no organization to this data. Instead, it's just a collection of numbers without any context. If this hash represented the nested nature of these calls, it could look like (newlines and formatting added):

{
  :server_dequeue => 0.0058367252349853516, 
  :ems_refresh => 149.55086016654968,
  :ems_refresh_timings => { 
    :collect_inventory_for_targets => 115.83132314682007, 
    :collect_inventory_for_targets_timings => {
      :get_ems_data => 9.814793109893799, 
      :get_vc_data => 89.20815706253052, 
      :filter_vc_data => 0.020371675491333008, 
      :get_vc_data_host_scsi => 16.73558282852173, 
    },
    :parse_targeted_inventory => 0.729581356048584, 
    :parse_targeted_inventory_timings => {
      :parse_vc_data => 0.729074239730835,
    },
    :save_inventory => 32.98742628097534,
    :save_inventory_timings => {
      :db_save_inventory => 32.98734211921692,
    }
  }
}

This gives a much clearer view, imo, of how these numbers actually compose a larger refresh timing.

I would love to see other examples of nested Benchmark.realtime_block log output that either corroborates or disproves the need for better timing grouping.

This issue was moved to this repository from https://github.com/ManageIQ/manageiq/issues/11692, originally opened by @blomquisg

This issue was moved to this repository from https://github.com/ManageIQ/manageiq-gems-pending/issues/420, originally opened by @miq-bot

ManageIQ / more_core_extensions

Make Benchmark Timing output more sensible #69