Bug 2011105
| Summary: | Viewing Remote Execution job invocation output scales very badly in the WebUI as output grows | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Dylan Gross <dgross> | ||||
| Component: | Remote Execution | Assignee: | satellite6-bugs <satellite6-bugs> | ||||
| Status: | CLOSED MIGRATED | QA Contact: | Peter Ondrejka <pondrejk> | ||||
| Severity: | medium | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 6.9.0 | CC: | ajambhul, aruzicka, david.deaderick, lstejska, wpinheir | ||||
| Target Milestone: | Unspecified | Keywords: | MigratedToJIRA, Performance, Triaged, UserExperience | ||||
| Target Release: | Unused | ||||||
| Hardware: | All | ||||||
| OS: | All | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2024-06-06 01:05:42 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
Created redmine issue https://projects.theforeman.org/issues/33674 from this bug From what I've seen everything goes quite fast, all data seems to be loaded under half a second, but rendering takes another twelve.
In the above comment c#3, is the "rendering" referring to the time it takes to show on the page, or how long the logs show it takes for "show.html.erb" to complete?
In this example, even though the logs showing it complete in about 12 seconds, it takes multiple minutes to show on page.
If it was closer to 12 seconds, I think that would be a welcome change.
$ grep 3fc66aee production.log
2021-10-04T09:11:21 [I|app|3fc66aee] Started GET "/template_invocations/196222" for x.x.x.x at 2021-10-04 09:11:21 -0500
2021-10-04T09:11:21 [I|app|3fc66aee] Processing by TemplateInvocationsController#show as HTML
2021-10-04T09:11:21 [I|app|3fc66aee] Parameters: {"id"=>"196222"}
2021-10-04T09:11:21 [I|app|3fc66aee] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-3.3.7.2/app/views/template_invocations/show.html.erb within layouts/application
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered collection of /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-3.3.7.2/app/views/template_invocations/_output_line_set.html.erb [4601 times] (Duration: 12271.1ms | Allocations: 30411214)
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-3.3.7.2/app/views/template_invocations/_refresh.js.erb (Duration: 1.4ms | Allocations: 218)
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-3.3.7.2/app/views/template_invocations/show.html.erb within layouts/application (Duration: 12379.4ms | Allocations: 30568376)
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered layouts/_application_content.html.erb (Duration: 4.4ms | Allocations: 6526)
2021-10-04T09:11:33 [I|app|3fc66aee] Rendering layouts/base.html.erb
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_theme_satellite-6.0.1.7/app/views/foreman_theme_satellite/_theme_client_side_branding.js.erb (Duration: 2.4ms | Allocations: 6903)
2021-10-04T09:11:33 [I|app|3fc66aee] Rendered layouts/base.html.erb (Duration: 48.0ms | Allocations: 37929)
2021-10-04T09:11:33 [I|app|3fc66aee] Completed 200 OK in 12910ms (Views: 12444.6ms | ActiveRecord: 5.1ms | Allocations: 31366146)
Yes, that's what I got from the logs, I was trying it with quite a small sample and it rendered just fine in the browser. However now I've tried with larger output (5k lines) and I finally got what you mean. The whole thing took roughly 2 minutes. Created attachment 1833021 [details] Performance graph Investigating this, it appears that most of the time after the server finishes handling the request is spent by the browser rendering the page (see screenshot, from a 6.10 satellite). This is due to the fact we render thousands of lines directly with no pagination, with several elements per line. We need to consider some way to reduce the number of rendered components - perhaps wrapping the output in a fixed-height div with scrollbar would be enough, but if not we'll need to implement some sort of pagination mechanism that would avoid rendering the full output directly. 6.8 and 6.9 might also be affected by https://projects.theforeman.org/issues/31990 which will be included in 6.10 and could also speed up the browser rendering (but not enough, as the layout render timing above is still slow in 6.10). Additionally, the server side render could be improved as well, https://github.com/theforeman/foreman_remote_execution/blob/master/app/views/template_invocations/_output_line_set.html.erb has many object allocations per line that could be reduced (30M allocations for a request as described in comment #4 is not reasonable). *** Bug 2083375 has been marked as a duplicate of this bug. *** This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there. Due to differences in account names between systems, some fields were not replicated. Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information. To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "SAT-" followed by an integer. You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like: "Bugzilla Bug" = 1234567 In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information. |
Description of problem: As the number of lines in the output of a host's Remote Execution grows, the speed at which the WebUI displays results gets very poor. (using hammer, however, seems unaffected) ** Someone double check the component I selected. I chose remote execution, but this is NOT a problem with the speed of actually executing. Rather it's just with viewing the output results once they're back on Satellite ** Version-Release number of selected component (if applicable): Reported/reproduced on Satellite 6.8.6 through 6.9.3 How reproducible: Reliably Steps to Reproduce: 1. (Presummption) - You can remote execute on a host 2. I created seven jobs to demonstrate this: for i in {1..10}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..100}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..1000}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..2000}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..3000}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..4000}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done for i in {1..5000}; do echo "Line ${i}: lest we get bored, here's a UUID: $(uuidgen)"; done Under "Hosts" -> "All Hosts" -> Select a single host -> "Schedule Remote Job" -> I used "Run command - SSH default" and put the one of the above lines in each job. 3. Go to: "Monitor" -> "Jobs". For each of the above jobs, click the job description: https://satellite/job_invocations/<job_invocation_id> Under the job invocation id, click the hostname to see the output: https://satellite/template_invocations/<template_invocation_id> Actual results: Viewing the output in the WebUI as described above results in a vastly skewed times, growing exponentially slower as output grows. Number of lines in output | Wall clock time | Log reported Completed 200 OK in <n>ms -------------------------------------------------------------------------------- 10 | < 1 second | 85ms 100 | < 1 second | 281ms 1000 | 8-10 seconds | 2263ms 2000 | ~14 seconds | 4179ms 3000 | ~48 seconds | 4130ms 4000 | ~1min 43 seconds | 8141ms 5000 | ~3min 07 seconds | 9223ms Expected results: I would hope for something more in line with the hammer times, which were only a couple seconds in worst case.: # time hammer job-invocation output --id <job id) --host myhostname 10 lines : real 0m1.503s user 0m0.969s sys 0m0.119s 100 lines : real 0m1.491s user 0m0.966s sys 0m0.116s 1000 lines : real 0m1.640s user 0m1.032s sys 0m0.107s 2000 lines : real 0m1.752s user 0m1.088s sys 0m0.111s 3000 lines : real 0m1.752s user 0m1.088s sys 0m0.111s 4000 lines : real 0m2.100s user 0m1.212s sys 0m0.110s 5000 lines : real 0m2.238s user 0m1.204s sys 0m0.104s