{"action":"created","issue":{"url":"https://api.github.com/repos/ManageIQ/manageiq/issues/11692","repository_url":"https://api.github.com/repos/ManageIQ/manageiq","labels_url":"https://api.github.com/repos/ManageIQ/manageiq/issues/11692/labels{/name}","comments_url":"https://api.github.com/repos/ManageIQ/manageiq/issues/11692/comments","events_url":"https://api.github.com/repos/ManageIQ/manageiq/issues/11692/events","html_url":"https://github.com/ManageIQ/manageiq/issues/11692","id":180977162,"number":11692,"title":"Make Benchmark Timing output more sensible","user":{"login":"blomquisg","id":14183,"avatar_url":"https://avatars.githubusercontent.com/u/14183?v=3","gravatar_id":"","url":"https://api.github.com/users/blomquisg","html_url":"https://github.com/blomquisg","followers_url":"https://api.github.com/users/blomquisg/followers","following_url":"https://api.github.com/users/blomquisg/following{/other_user}","gists_url":"https://api.github.com/users/blomquisg/gists{/gist_id}","starred_url":"https://api.github.com/users/blomquisg/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/blomquisg/subscriptions","organizations_url":"https://api.github.com/users/blomquisg/orgs","repos_url":"https://api.github.com/users/blomquisg/repos","events_url":"https://api.github.com/users/blomquisg/events{/privacy}","received_events_url":"https://api.github.com/users/blomquisg/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-10-04T19:04:02Z","updated_at":"2016-10-04T19:07:22Z","closed_at":null,"body":"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.\r\n\r\nFor 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:\r\n\r\n```\r\n- ems_refresh\r\n| - collect_inventory_for_targets\r\n  | - get_ems_data\r\n  | - get_vc_data\r\n  | - get_vc_data_ems_customization_specs (optional)\r\n  | - filter_vc_data\r\n  | - get_vc_data_host_scsi\r\n| - parse_targeted_inventory\r\n  | - parse_vc_data\r\n| - save_inventory\r\n  | - db_save_inventory\r\n```\r\n\r\nHowever, this is what we currently output when we capture the `Benchmark.realtime_block`: \r\n\r\n```\r\n[----] I, [2016-09-25T20:29:39.651349 #30193:ea3990] INFO -- : \r\nMIQ(ManageIQ::Providers::Vmware::InfraManager::Refresher#refresh) \r\nEMS: [EMS NAME], id: [50000000000004] Refreshing targets for EMS...Complete - \r\nTimings {:server_dequeue=>0.0058367252349853516, :get_ems_data=>9.814793109893799, \r\n:get_vc_data=>89.20815706253052, :filter_vc_data=>0.020371675491333008, \r\n:get_vc_data_host_scsi=>16.73558282852173, \r\n:collect_inventory_for_targets=>115.83132314682007, :parse_vc_data=>0.729074239730835, \r\n:parse_targeted_inventory=>0.729581356048584, :db_save_inventory=>32.98734211921692, \r\n:save_inventory=>32.98742628097534, :ems_refresh=>149.55086016654968}\r\n```\r\n\r\nIf I scale that back to just the hash of timings, it looks like (newlines and formatting added):\r\n\r\n```\r\n{\r\n :server_dequeue                => 0.0058367252349853516, \r\n :get_ems_data                  => 9.814793109893799, \r\n :get_vc_data                   => 89.20815706253052, \r\n :filter_vc_data                => 0.020371675491333008, \r\n :get_vc_data_host_scsi         => 16.73558282852173, \r\n :collect_inventory_for_targets => 115.83132314682007, \r\n :parse_vc_data                 => 0.729074239730835, \r\n :parse_targeted_inventory      => 0.729581356048584, \r\n :db_save_inventory             => 32.98734211921692, \r\n :save_inventory                => 32.98742628097534, \r\n :ems_refresh                   => 149.55086016654968\r\n}\r\n```\r\n\r\nThere'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):\r\n\r\n```\r\n{\r\n  :server_dequeue => 0.0058367252349853516, \r\n  :ems_refresh => 149.55086016654968,\r\n  :ems_refresh_timings => { \r\n    :collect_inventory_for_targets => 115.83132314682007, \r\n    :collect_inventory_for_targets_timings => {\r\n      :get_ems_data => 9.814793109893799, \r\n      :get_vc_data => 89.20815706253052, \r\n      :filter_vc_data => 0.020371675491333008, \r\n      :get_vc_data_host_scsi => 16.73558282852173, \r\n    },\r\n    :parse_targeted_inventory => 0.729581356048584, \r\n    :parse_targeted_inventory_timings => {\r\n      :parse_vc_data => 0.729074239730835,\r\n    },\r\n    :save_inventory => 32.98742628097534,\r\n    :save_inventory_timings => {\r\n      :db_save_inventory => 32.98734211921692,\r\n    }\r\n  }\r\n}\r\n```\r\n\r\nThis gives a much clearer view, imo, of how these numbers actually compose a larger refresh timing.\r\n\r\nI would love to see other examples of nested `Benchmark.realtime_block` log output that either corroborates or disproves the need for better timing grouping."},"comment":{"url":"https://api.github.com/repos/ManageIQ/manageiq/issues/comments/251482802","html_url":"https://github.com/ManageIQ/manageiq/issues/11692#issuecomment-251482802","issue_url":"https://api.github.com/repos/ManageIQ/manageiq/issues/11692","id":251482802,"user":{"login":"Fryguy","id":52120,"avatar_url":"https://avatars.githubusercontent.com/u/52120?v=3","gravatar_id":"","url":"https://api.github.com/users/Fryguy","html_url":"https://github.com/Fryguy","followers_url":"https://api.github.com/users/Fryguy/followers","following_url":"https://api.github.com/users/Fryguy/following{/other_user}","gists_url":"https://api.github.com/users/Fryguy/gists{/gist_id}","starred_url":"https://api.github.com/users/Fryguy/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Fryguy/subscriptions","organizations_url":"https://api.github.com/users/Fryguy/orgs","repos_url":"https://api.github.com/users/Fryguy/repos","events_url":"https://api.github.com/users/Fryguy/events{/privacy}","received_events_url":"https://api.github.com/users/Fryguy/received_events","type":"User","site_admin":false},"created_at":"2016-10-04T19:07:22Z","updated_at":"2016-10-04T19:07:22Z","body":"Alternately (if we reserved the `:total` keyword or something similar)\r\n\r\n```ruby\r\n{\r\n  :server_dequeue => 0.0058367252349853516, \r\n  :ems_refresh => { \r\n    :total => 149.55086016654968,\r\n    :collect_inventory_for_targets => {\r\n      :total => 115.83132314682007,\r\n      :get_ems_data => 9.814793109893799, \r\n      :get_vc_data => 89.20815706253052, \r\n      :filter_vc_data => 0.020371675491333008, \r\n      :get_vc_data_host_scsi => 16.73558282852173, \r\n    },\r\n    :parse_targeted_inventory => {\r\n      :total => 0.729581356048584,\r\n      :parse_vc_data => 0.729074239730835,\r\n    },\r\n    :save_inventory => {\r\n      :total => 32.98742628097534,\r\n      :db_save_inventory => 32.98734211921692,\r\n    }\r\n  }\r\n}\r\n```"}}
{"actor":{"display_login":"Fryguy"}}