Description of problem: I would expect that with service dialog targeted element refresh that for any given up date of a source element that the targeted elements should only be refreshed once. What I am seeing is that the targeted items are being refreshed countless times. To the point of a single refresh taking minutes. This problem seems to compound the more items are targeted from a single source. The issue may also be worse when using multi select dialog boxes but I am unclear on that. Version-Release number of selected component (if applicable): 5.9.2.4.20180501195858_35dc609 How reproducible: Always Steps to Reproduce: This is reproducible with the domains and catalog items linked in the additional information section. The steps to reproduce are based on what I *think* is the minimal instructions needed to get our service dialog working in a new environment. The full instructions can be found here: https://github.com/RedHatOfficial/miq-RedHat-Satellite6/blob/master/INSTALL.md 1. Import domains 2. Import service dialog 3. Import service catalog 4. https://github.com/RedHatOfficial/miq-RedHat-Satellite6/blob/master/INSTALL.md#tagging 5. https://github.com/RedHatOfficial/miq-RedHat-Satellite6/blob/master/INSTALL.md#network-configuration Actual results: Each time a source dialog element is changed, the target elements are refrshed dozens of times. Expected results: Each targeted dialog element is only refreshed once on a source element update. Additional info: Example dialog: https://github.com/RedHatOfficial/miq-RedHat-Satellite6/blob/master/Dialogs/v5.9/Satellite_Provisioning.yml Example service catalog item: https://github.com/RedHatOfficial/miq-RedHat-Satellite6/blob/master/Catalogs/v5.9/Hybrid_Cloud_VMs.yml Domains: * https://github.com/RedHatOfficial/miq-RedHat-Satellite6 * https://github.com/RedHatOfficial/miq-Utilities
Well something is weird. I reproduced this 100s of times leading up to and even during my summit presentation. Every single time I had this issue. But I just went to reproduce and capture the log output, and the dialog refreshed in seconds rather then the minutes it used to take. I have changed nothing on my side. Looking at log outputs each item is still being refreshed multiple times, but not exponential number of times.
Okay. I figured out why I was going crazy. This works differently on the admin UI vs the self service UI. Admin UI is snappy and from logs each element, though refreshed a few times, gets through it quick. The self service UI on the other hand refreshes dozens of times and takes minutes. So it is odd that in both cases i see targeted elements refreshing more then 1 time, but its super bad on the service UI where the counts are so high as to cause refreshes to take minutes. I will attach logs from both use cases for the same dialog.
Created attachment 1436511 [details] automation.log - initially loading service catalog item in admin UI
Created attachment 1436513 [details] automation.log - admin UI - cause a refresh of dialog elements
Created attachment 1436514 [details] automation.log - service UI - initially loading service catalog item
Created attachment 1436515 [details] automation.log - service UI - cause a refresh of dialog elements
For instance, one of the dialog elements gets refreshed 44 times in the service UI vs 4 times in the admin UI for the same action.
@drew ``` [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2" automation.log-admin_ui-cause_refresh | wc -l 4 [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2" automation.log-service_ui-cause_refresh | wc -l 44 ``` for any given destination provider index for the `get_networks` method should only in theory be called once as it is only being targeted for a refresh from one element.
Hey Ian! Could you confirm a suspicion for me please? If you edit the dialog, clear your logs, and remove one of the location boxes on the infra tab (so you only have three) and then rerun the dialog can you tell me what that grep count is from that run please?
Drew, I refined my grep a bit because i forgot for each location there are two dialog elements that call get_networks for a given index, one for provisioning and one for destination. So for with 4 location boxes i get: ``` [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2, \"network_purpose\"=>\"provisioning\"" automation.log-service_ui-cause_refresh | wc -l 22 [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2, \"network_purpose\"=>\"provisioning\"" automation.log-admin_ui-cause_refresh | wc -l 2 ``` for 3 location boxes I get: ``` [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2, \"network_purpose\"=>\"provisioning\"" automation.log-service_ui-cause_refresh-2 | wc -l 13 [root@summit-cfme tmp]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>2, \"network_purpose\"=>\"provisioning\"" automation.log-admin_ui-cause_refresh-2 | wc -l 2 ``` will attach new logs.
Created attachment 1437334 [details] automation.log - admin UI - initial loading service catalog item - (3 location boxes)
Created attachment 1437335 [details] automation.log - admin UI - cause a refresh of dialog elements (3 location boxes)
Created attachment 1437336 [details] automation.log - service UI - initially loading service catalog item (3 location boxes)
Created attachment 1437337 [details] automation.log - service UI - cause a refresh of dialog elements (3 location boxes)
Interestingly enough, the service UI run of this setup on master appears to only run those methods once: ~/manageiq/log [master ↑·3614|…1] 11:17 $ grep "get_networks] with inputs \[{\"destination_provider_index\"=>3, \"network_purpose\"=>\"provisioning\"" automation.log | wc -l 1 ✔ ~/manageiq/log [master ↑·3614|…1] 11:17 $ grep "get_networks] with inputs \[{\"destination_provider_index\"=>2, \"network_purpose\"=>\"provisioning\"" automation.log | wc -l 1 ✔ ~/manageiq/log [master ↑·3614|…1] 11:17 $ grep "get_networks] with inputs \[{\"destination_provider_index\"=>1, \"network_purpose\"=>\"provisioning\"" automation.log | wc -l 1 ✔ ~/manageiq/log [master ↑·3614|…1] 11:17 $ grep "get_networks] with inputs \[{\"destination_provider_index\"=>0, \"network_purpose\"=>\"provisioning\"" automation.log | wc -l 1
@Drew, Are you saying you can't reproduce in your setup? Blue skies, Ian
On 5.9.2.4.20180501195858_35dc609 (same build as listed version) my SUI run of this setup got single runs for this setup too: [root@dhcp-8-198-69 log]# grep "get_networks] with inputs \[{\"destination_provider_index\"=>0, \"network_purpose\"=>\"provisioning\"" automation.log | wc -l 1 Ian, any chance you might be willing to give me access to your appliance on which this bug can be reproduced since I seem to be unable to do so? Thanks.
@drew, Sent you email with connection info.
Created attachment 1438490 [details] Satellite_Provisioning.yml - dialog that can reproduce issue
I'm seeing that the locations are linked to the Providers and Templates field, so every time the locations field changes, automate must run the methods on any field linked to the Providers and Templates field, which is all of the source/destination fields. The count also seem to increment when env/hostgroup fields are changed which also makes sense since their values are dependent on that of the locations. I don't believe this is a bug in our code.
@drew, Can we get on a BlueJeans? Based on the difference in behavior between then self service ui and the admin UI i am 99% confident there is a bug here. I am available at the following times today 9:00am EST 11:00am EST 2:00pm EST Shoot me an email with what works for you and we can sort quickly I bet. Blue skies, Ian
Do we agree that this is an SUI issue only?
@drew, Yes. I don't see the issue in the admin UI as outlined in Comment #14. For the same operation I get 22 refreshes in the Service UI (with the large time delay because of it) and 2 refreshes in the Admin UI (with no noticeable time delay). So I would say squarely only an issue with the service UI. My apologies if I didn't make that clear enough earlier. Blue skies, Ian
https://github.com/ManageIQ/manageiq-ui-service/pull/1438 and an api pr that will be forthcoming
https://github.com/ManageIQ/manageiq-api/pull/386
The API PR is not required to fix this issue.
New commit detected on ManageIQ/manageiq-api/master: https://github.com/ManageIQ/manageiq-api/commit/4a1153478b565128c5a6fe9972077c72812a3369 commit 4a1153478b565128c5a6fe9972077c72812a3369 Author: Erik Clarizio <eclarizio> AuthorDate: Tue May 29 11:40:59 2018 -0400 Commit: Erik Clarizio <eclarizio> CommitDate: Tue May 29 11:40:59 2018 -0400 Ensure refresh => true option gets passed for service_template refresh https://bugzilla.redhat.com/show_bug.cgi?id=1578080 app/controllers/api/subcollections/service_templates.rb | 6 +- spec/requests/service_catalogs_spec.rb | 12 + 2 files changed, 15 insertions(+), 3 deletions(-)
The dialog is very slow to load in 5.10 and I am seeing automate methods called multiple times. @drew can you please take a look . Appliance : https://10.8.199.21/ ======================= tail -f /var/www/miq/vmdb/log/automation.log|grep "Starting\|Ending" [----] I, [2018-07-18T16:07:51.099594 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cloud_flavors]> Ending [----] I, [2018-07-18T16:07:51.692147 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cloud_ssh_keys]> Starting [----] I, [2018-07-18T16:07:52.523073 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cloud_ssh_keys]> Ending [----] I, [2018-07-18T16:12:32.142627 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_vm_counts]> Starting [----] I, [2018-07-18T16:12:35.745333 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_vm_counts]> Starting [----] I, [2018-07-18T16:12:46.316014 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_vm_counts]> Ending [----] I, [2018-07-18T16:12:46.928664 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cpu_sizes]> Starting [----] I, [2018-07-18T16:13:14.210793 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_vm_counts]> Ending [----] I, [2018-07-18T16:13:14.949121 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cpu_sizes]> Starting [----] I, [2018-07-18T16:13:21.272382 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cpu_sizes]> Ending [----] I, [2018-07-18T16:13:21.928642 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_memory_sizes]> Starting [----] I, [2018-07-18T16:13:29.428049 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_cpu_sizes]> Ending [----] I, [2018-07-18T16:13:30.035938 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_memory_sizes]> Starting [----] I, [2018-07-18T16:13:39.308583 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_memory_sizes]> Ending [----] I, [2018-07-18T16:13:39.309604 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/DynamicDialogs/get_memory_sizes]> Ending [----] I, [2018-07-18T16:13:39.921677 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/System/DynamicDialogs/get_tags]> Starting [----] I, [2018-07-18T16:13:39.976197 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/System/DynamicDialogs/get_tags]> Starting [----] I, [2018-07-18T16:14:05.121520 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Utilities/System/DynamicDialogs/get_tags]> Ending [----] I, [2018-07-18T16:14:05.170088 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Utilities/System/DynamicDialogs/get_tags]> Ending [----] I, [2018-07-18T16:14:05.583962 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_organizations]> Starting [----] I, [2018-07-18T16:14:05.872715 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_organizations]> Starting [----] I, [2018-07-18T16:14:30.873984 #12070:742221c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:14:30.910860 #12070:7419d88] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:14:59.054994 #12070:742221c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:14:59.060009 #12070:7419d88] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:14:59.342702 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_organizations]> Ending [----] I, [2018-07-18T16:14:59.343633 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_organizations]> Ending [----] I, [2018-07-18T16:14:59.852834 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_locations_by_tag_path]> Starting [----] I, [2018-07-18T16:15:00.116874 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_locations_by_tag_path]> Starting [----] I, [2018-07-18T16:15:09.007705 #12070:a210a20] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:15:09.031128 #12070:a216f9c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:15:24.907800 #12070:a216f9c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:15:24.969363 #12070:a210a20] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:15:25.072859 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_locations_by_tag_path]> Ending [----] I, [2018-07-18T16:15:25.189273 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_locations_by_tag_path]> Ending [----] I, [2018-07-18T16:15:25.464276 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_lifecycle_environments_filtered_by_tags]> Starting [----] I, [2018-07-18T16:15:25.520347 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_lifecycle_environments_filtered_by_tags]> Starting [----] I, [2018-07-18T16:15:34.463153 #12070:c69a670] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:15:34.655388 #12070:c69b368] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:15:58.503523 #12070:c69a670] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:15:58.505209 #12070:c69b368] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Ending [----] I, [2018-07-18T16:15:58.694088 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_lifecycle_environments_filtered_by_tags]> Ending [----] I, [2018-07-18T16:15:58.699266 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_lifecycle_environments_filtered_by_tags]> Ending [----] I, [2018-07-18T16:15:58.911995 #12070:3bd8258] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_hostgroups]> Starting [----] I, [2018-07-18T16:15:58.991763 #12070:3bd4c0c] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/DynamicDialogs/get_hostgroups]> Starting [----] I, [2018-07-18T16:16:12.851906 #12070:cda9100] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting [----] I, [2018-07-18T16:16:13.055346 #12070:cda8570] INFO -- : <AEMethod [/RedHatConsulting_Satellite6/Integration/Satellite/Configuration/get_satellite_configuration]> Starting
Hey Shveta! I asked Ian some weeks ago to provide an updated copy of the dialog because the one on this ticket doesn't have the field responders set up correctly. The dialog that's referenced here isn't using some of the latest code. Unfortunately I never did get an attachment on the ticket per my request, and so without a dialog that's a valid representation of the codebase on the version of this appliance I'm afraid that I believe the performance issues with this particular dialog are due to the complexity of the dialog itself. We've a couple of evm instantiations in the automate code and the setup is decently complex. I think this is expected behavior. Automate is being called as many times as I would expect for this dialog. I don't know what else to tell you, sorry.
Hey Drew and Shveta, sorry, i dropped the ball. The latest dialogs should be here: https://github.com/RedHatOfficial/miq-RedHat-Satellite6/tree/master/Dialogs/v5.9
Hey Ian! Sorry about this but that link doesn't have dialog_field_responders: [] even listed as a yml field and I was hoping that not only would it, it might also have them set.
The updated field responder system is detailed in a(n as-yet unmerged, WIP) post here: https://github.com/ManageIQ/manageiq.org/pull/663/files.
@drew, is it something that would export when I export the dialogs form CFME or do I need to do something else? I am pretty sure those are the latest exported from my environment, but I can try again.
Other than the multiple automate calls the original issue is fixed. Verified in 5.10.0.3.20180705151325_ce4d2b5
Just for clarification, the multiple automate calls were fixed by these PRs. The dialog performance itself is due to a couple factors, one being nested automate calls, one being the fact that there are multiple evm instantiations happening (each which introduce increasing overhead in terms of time). The performance I really don't believe can be fixed by changes to anything other than the dialog and custom code. If anyone thinks that 1) the performance 2) the fact that the export dialogs don't seem to have field responders like they should are still issues, please open other tickets as the original issue for this I believe has been seen to. Thanks!
@drew, so long as there arn't multiple automate calls any more the issue is fixed from my perspective. As I *think* i said earlier in this bug report this was only happening in the service UI, in the OPS UI performance had 0 issues, but it also wasnt making so many automate calls. So so long as the automate calls have been normalized for the service UI to the same level they are for the OPS UI we are good. so do you all still need anything from me?
i am going to assume you don't need anything from me any more since this patch has been shipped. marking info as provided.