realtime_block for each InventoryCollection saved

[cben]

Revival of #15746 (github won't let me reopen it after I rebased the branch) — may be desirable now that #16442 moved most graph refresh logging to debug.

raw log snippet after running EmsRefresh.refresh — timing hash is all on one (very long) line:

[----] I, [2017-11-28T15:58:45.608372 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) Refreshing all targets...
[----] I, [2017-11-28T15:58:45.608716 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Refreshing targets for EMS...
[----] I, [2017-11-28T15:58:45.608921 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1]   ManageIQ::Providers::Openshift::ContainerManager [vm-48-131.eng.lab.tlv.redhat.com] id [1]
[----] I, [2017-11-28T15:58:45.611824 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::Openshift::ContainerManager: [vm-48-131.eng.lab.tlv.redhat.com]
[----] I, [2017-11-28T15:58:47.239439 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::Openshift::ContainerManager: [vm-48-131.eng.lab.tlv.redhat.com]
[----] I, [2017-11-28T15:58:49.702850 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Refreshing target ManageIQ::Providers::Openshift::ContainerManager [vm-48-131.eng.lab.tlv.redhat.com] id [1]...
[----] I, [2017-11-28T15:58:50.902064 #3092:2ae7969830d4]  INFO -- : MIQ(ManagerRefresh::SaveInventory.save_inventory) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Saving EMS Inventory...
[----] I, [2017-11-28T15:58:53.975674 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [recycler-for-pv0003] id [562] from EMS [vm-48-131.eng.lab.tlv.redhat.com] id [1]
[----] I, [2017-11-28T15:58:54.114766 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [pv-recycler] id [564] from EMS
[----] I, [2017-11-28T15:58:55.250328 #3092:2ae7969830d4]  INFO -- : MIQ(ManagerRefresh::SaveInventory.save_inventory) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Saving EMS Inventory...Complete
[----] I, [2017-11-28T15:58:55.250956 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Refreshing target ManageIQ::Providers::Openshift::ContainerManager [vm-48-131.eng.lab.tlv.redhat.com] id [1]...Complete
[----] I, [2017-11-28T15:58:55.251397 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] ManagerRefresh Post Processing ManageIQ::Providers::Openshift::ContainerManager [vm-48-131.eng.lab.tlv.redhat.com] id [1]...
[----] I, [2017-11-28T15:58:55.252012 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] ManagerRefresh Post Processing ManageIQ::Providers::Openshift::ContainerManager [vm-48-131.eng.lab.tlv.redhat.com] id [1]...Complete
[----] I, [2017-11-28T15:58:55.252923 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [vm-48-131.eng.lab.tlv.redhat.com], id: [1] Refreshing targets for EMS...Complete - Timings {:collect_inventory_for_targets=>4.093669176101685, :parse_targeted_inventory=>1.1590373516082764, "SaveCollection container_projects"=>0.03934311866760254, "SaveCollection container_limits"=>0.0574643611907959, "SaveCollection container_limit_items"=>0.09664416313171387, "SaveCollection container_nodes"=>0.040674448013305664, "SaveCollection container_image_registries"=>0.06819009780883789, "SaveCollection mapped_tags_to_resolve"=>0.00015020370483398438, "SaveCollection container_quotas"=>0.057775259017944336, "SaveCollection container_conditions_for_container_nodes"=>0.02277231216430664, "SaveCollection computer_systems"=>0.06786227226257324, "SaveCollection container_images"=>0.19092178344726562, "SaveCollection container_replicators"=>0.023134469985961914, "SaveCollection container_templates"=>1.073012351989746, "SaveCollection container_builds"=>0.06642007827758789, "SaveCollection persistent_volume_claims"=>0.06717061996459961, "SaveCollection custom_attributes_for_container_projects_labels"=>0.017606258392333984, "SaveCollection custom_attributes_for_container_projects_additional_attributes"=>0.014680624008178711, "SaveCollection taggings_for_container_projects"=>0.04351496696472168, "SaveCollection custom_attributes_for_container_nodes_labels"=>0.03457450866699219, "SaveCollection custom_attributes_for_container_nodes_additional_attributes"=>0.005848884582519531, "SaveCollection taggings_for_container_nodes"=>0.00828409194946289, "SaveCollection container_quota_items"=>0.06606030464172363, "SaveCollection computer_system_hardwares"=>0.0610661506652832, "SaveCollection computer_system_operating_systems"=>0.08553457260131836, "SaveCollection container_template_parameters"=>0.19815587997436523, "SaveCollection container_build_pods"=>0.03712940216064453, "SaveCollection persistent_volumes"=>0.10788822174072266, "SaveCollection custom_attributes_for_container_replicators_labels"=>0.03616046905517578, "SaveCollection custom_attributes_for_container_replicators_selectors"=>0.025938034057617188, "SaveCollection taggings_for_container_replicators"=>0.004203319549560547, "SaveCollection custom_attributes_for_container_templates_labels"=>0.023299694061279297, "SaveCollection taggings_for_container_templates"=>0.0074579715728759766, "SaveCollection custom_attributes_for_container_builds_labels"=>0.017942428588867188, "SaveCollection taggings_for_container_builds"=>0.0079193115234375, "SaveCollection custom_attributes_for_container_images_labels"=>0.006956815719604492, "SaveCollection custom_attributes_for_container_images_docker_labels"=>0.17036676406860352, "SaveCollection taggings_for_container_images"=>0.003935813903808594, "SaveCollection container_groups"=>0.38121676445007324, "SaveCollection custom_attributes_for_container_build_pods_labels"=>0.030466794967651367, "SaveCollection taggings_for_container_build_pods"=>0.01308751106262207, "SaveCollection container_conditions_for_container_groups"=>0.042897939682006836, "SaveCollection container_volumes"=>0.10119509696960449, "SaveCollection containers"=>0.10320377349853516, "SaveCollection container_services"=>0.3271167278289795, "SaveCollection custom_attributes_for_container_groups_labels"=>0.03476762771606445, "SaveCollection custom_attributes_for_container_groups_node_selectors"=>0.014539718627929688, "SaveCollection taggings_for_container_groups"=>0.015503644943237305, "SaveCollection container_port_configs"=>0.05925440788269043, "SaveCollection container_env_vars"=>0.07065606117248535, "SaveCollection security_contexts"=>0.07213568687438965, "SaveCollection container_service_port_configs"=>0.07243156433105469, "SaveCollection container_routes"=>0.026189088821411133, "SaveCollection custom_attributes_for_container_services_labels"=>0.018072843551635742, "SaveCollection custom_attributes_for_container_services_selectors"=>0.01911330223083496, "SaveCollection taggings_for_container_services"=>0.010002613067626953, "SaveCollection custom_attributes_for_container_routes_labels"=>0.018532514572143555, "SaveCollection taggings_for_container_routes"=>0.009307384490966797, :save_inventory=>4.388560771942139, :manager_refresh_post_processing=>0.00018405914306640625, :ems_refresh=>9.643144607543945}
[----] I, [2017-11-28T15:58:55.484246 #3092:2ae7969830d4]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) Refreshing all targets...Complete

same timing, pretty printed:
(note how thanks to magic of ruby ordered Hash, it is structured chronologically — all the SaveCollection are before :save_inventory.)

{:collect_inventory_for_targets=>4.093669176101685,
 :parse_targeted_inventory=>1.1590373516082764,
 "SaveCollection container_projects"=>0.03934311866760254,
 "SaveCollection container_limits"=>0.0574643611907959,
 "SaveCollection container_limit_items"=>0.09664416313171387,
 "SaveCollection container_nodes"=>0.040674448013305664,
 "SaveCollection container_image_registries"=>0.06819009780883789,
 "SaveCollection mapped_tags_to_resolve"=>0.00015020370483398438,
 "SaveCollection container_quotas"=>0.057775259017944336,
 "SaveCollection container_conditions_for_container_nodes"=>0.02277231216430664,
 "SaveCollection computer_systems"=>0.06786227226257324,
 "SaveCollection container_images"=>0.19092178344726562,
 "SaveCollection container_replicators"=>0.023134469985961914,
 "SaveCollection container_templates"=>1.073012351989746,
 "SaveCollection container_builds"=>0.06642007827758789,
 "SaveCollection persistent_volume_claims"=>0.06717061996459961,
 "SaveCollection custom_attributes_for_container_projects_labels"=>0.017606258392333984,
 "SaveCollection custom_attributes_for_container_projects_additional_attributes"=>0.014680624008178711,
 "SaveCollection taggings_for_container_projects"=>0.04351496696472168,
 "SaveCollection custom_attributes_for_container_nodes_labels"=>0.03457450866699219,
 "SaveCollection custom_attributes_for_container_nodes_additional_attributes"=>0.005848884582519531,
 "SaveCollection taggings_for_container_nodes"=>0.00828409194946289,
 "SaveCollection container_quota_items"=>0.06606030464172363,
 "SaveCollection computer_system_hardwares"=>0.0610661506652832,
 "SaveCollection computer_system_operating_systems"=>0.08553457260131836,
 "SaveCollection container_template_parameters"=>0.19815587997436523,
 "SaveCollection container_build_pods"=>0.03712940216064453,
 "SaveCollection persistent_volumes"=>0.10788822174072266,
 "SaveCollection custom_attributes_for_container_replicators_labels"=>0.03616046905517578,
 "SaveCollection custom_attributes_for_container_replicators_selectors"=>0.025938034057617188,
 "SaveCollection taggings_for_container_replicators"=>0.004203319549560547,
 "SaveCollection custom_attributes_for_container_templates_labels"=>0.023299694061279297,
 "SaveCollection taggings_for_container_templates"=>0.0074579715728759766,
 "SaveCollection custom_attributes_for_container_builds_labels"=>0.017942428588867188,
 "SaveCollection taggings_for_container_builds"=>0.0079193115234375,
 "SaveCollection custom_attributes_for_container_images_labels"=>0.006956815719604492,
 "SaveCollection custom_attributes_for_container_images_docker_labels"=>0.17036676406860352,
 "SaveCollection taggings_for_container_images"=>0.003935813903808594,
 "SaveCollection container_groups"=>0.38121676445007324,
 "SaveCollection custom_attributes_for_container_build_pods_labels"=>0.030466794967651367,
 "SaveCollection taggings_for_container_build_pods"=>0.01308751106262207,
 "SaveCollection container_conditions_for_container_groups"=>0.042897939682006836,
 "SaveCollection container_volumes"=>0.10119509696960449,
 "SaveCollection containers"=>0.10320377349853516,
 "SaveCollection container_services"=>0.3271167278289795,
 "SaveCollection custom_attributes_for_container_groups_labels"=>0.03476762771606445,
 "SaveCollection custom_attributes_for_container_groups_node_selectors"=>0.014539718627929688,
 "SaveCollection taggings_for_container_groups"=>0.015503644943237305,
 "SaveCollection container_port_configs"=>0.05925440788269043,
 "SaveCollection container_env_vars"=>0.07065606117248535,
 "SaveCollection security_contexts"=>0.07213568687438965,
 "SaveCollection container_service_port_configs"=>0.07243156433105469,
 "SaveCollection container_routes"=>0.026189088821411133,
 "SaveCollection custom_attributes_for_container_services_labels"=>0.018072843551635742,
 "SaveCollection custom_attributes_for_container_services_selectors"=>0.01911330223083496,
 "SaveCollection taggings_for_container_services"=>0.010002613067626953,
 "SaveCollection custom_attributes_for_container_routes_labels"=>0.018532514572143555,
 "SaveCollection taggings_for_container_routes"=>0.009307384490966797,
 :save_inventory=>4.388560771942139,
 :manager_refresh_post_processing=>0.00018405914306640625,
 :ems_refresh=>9.643144607543945}

@Fryguy @agrare @Ladas what do you think?

[Ladas]

@cben @agrare I would still like to see how many create/updated/deleted objects are associated to that time

[miq-bot]

Checked commit cben@8fc3ee0 with ruby 2.3.3, rubocop 0.47.1, haml-lint 0.20.0, and yamllint 1.10.0
1 file checked, 0 offenses detected
Everything looks fine. 🏆

[Ladas]

@agrare this gives us time of each collection for perf debugging and order of saving of the graph. So depends on you, I like it :-)

[agrare]

Personally I think this is too much detail unless you are trying to debug something very specific. Generally I don't see this being useful for customers/support and adds to the noise.

If there were a way to only run the benchmark if debug were enabled that would work.

[cben]

OK, closing. Not a big fan of "if debug", and for local testing, I just cherry-pick this :-)

git fetch origin pull/16536/head; git cherry-pick FETCH_HEAD --no-commit