Hide Forgot
Description of problem: Satelllite Audits page is very slow Version-Release number of selected component (if applicable): Satellite 6.4.2 How reproducible: Always Steps to Reproduce: 1.Navigate to Satellite UI -> Monitor -> Audits page. Actual results: It took 37 seconds to load this page. (production.log postgresql.log attached) /var/log/foreman/production.log: 2019-04-26T10:57:42 [I|app|97741] Completed 200 OK in 37373ms (Views: 265.2ms | ActiveRecord: 15229.5ms) # time curl -k -u admin https://satellite.example.com/api/audits > audit Enter host password for user 'admin': % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 13950 0 13950 0 0 817 0 --:--:-- 0:00:17 --:--:-- 3534 real 0m19.485s user 0m0.047s sys 0m0.066s # head audit { "total": 5136427, "subtotal": 5136427, "page": 1, "per_page": 30, "search": null, "sort": { "by": null, "order": null }, Note: - The response time increases with the number of audit entries. In the above example, I had 5.1 mill entries. - The response time also increases in a production satellite with live traffic, the satellite I used had zero client production traffic. Expected results: Audit page should load faster Additional info:
Created attachment 1559180 [details] production.log
Created attachment 1559181 [details] postgrsql log
There are a couple of queries that make this call slow. I will try to outline my findings and possible solution where I can: 1. SELECT DISTINCT "audits"."auditable_type" FROM "audits"; Takes 2/40s From: /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/calculations.rb:176:in `pluck' /usr/share/foreman/app/models/concerns/audit_extensions.rb:96:in `known_auditable_types' /usr/share/foreman/app/models/concerns/audit_extensions.rb:86:in `untaxable' /usr/share/foreman/app/models/concerns/audit_extensions.rb:13:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /usr/share/foreman/app/models/concerns/audit_extensions.rb:26:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `public_send' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `block in method_missing' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `method_missing' /usr/share/foreman/app/controllers/audits_controller.rb:19:in `resource_base' /usr/share/foreman/app/controllers/application_controller.rb:227:in `resource_base_with_search' Can be mitigated by adding an index on auditable_type to audits table. 2. SELECT "audits"."id" FROM "audits"; Takes 3.5/40s (for the query only, I didn't measure Ruby time) From: /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/calculations.rb:176:in `pluck' /usr/share/foreman/app/models/concerns/taxonomix.rb:89:in `taxable_ids' /usr/share/foreman/app/models/concerns/taxonomix.rb:143:in `scope_by_taxable_ids' /usr/share/foreman/app/models/concerns/taxonomix.rb:47:in `with_taxonomy_scope' /usr/share/foreman/app/models/concerns/audit_extensions.rb:23:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /usr/share/foreman/app/models/concerns/audit_extensions.rb:26:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `public_send' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `block in method_missing' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `method_missing' /usr/share/foreman/app/controllers/audits_controller.rb:19:in `resource_base' /usr/share/foreman/app/controllers/application_controller.rb:227:in `resource_base_with_search' taxonomix.rb#taxable_ids should be refactored to something more restricted than bringing all ids from the table to memory. 3. SELECT audits.id FROM "audits"; Takes 3.5/40s (DB time + unknown ruby time) From: /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/calculations.rb:176:in `pluck' /usr/share/foreman/app/models/concerns/taxonomix.rb:111:in `inner_ids' /usr/share/foreman/app/models/concerns/taxonomix.rb:90:in `taxable_ids' /usr/share/foreman/app/models/concerns/taxonomix.rb:143:in `scope_by_taxable_ids' /usr/share/foreman/app/models/concerns/taxonomix.rb:47:in `with_taxonomy_scope' /usr/share/foreman/app/models/concerns/audit_extensions.rb:23:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /usr/share/foreman/app/models/concerns/audit_extensions.rb:26:in `block (2 levels) in <module:AuditExtensions>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `instance_exec' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block (2 levels) in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/scoping/named.rb:171:in `block in scope' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `public_send' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `block in method_missing' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation.rb:336:in `scoping' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/relation/delegation.rb:90:in `method_missing' /usr/share/foreman/app/controllers/audits_controller.rb:19:in `resource_base' /usr/share/foreman/app/controllers/application_controller.rb:227:in `resource_base_with_search' Should be part of refactoring from #2 / caching of the ids. 4. SELECT "audits".* FROM "audits" WHERE ((("audits"."auditable_type" IN ('Operatingsystem', 'Puppetclass', 'ConfigGroupClass', 'LookupKey', 'JobInvocation', 'Katello::Repository', 'LookupValue', 'HostgroupClass', 'PuppetclassLookupKey', 'ComputeProfile', 'HostClass', 'ComputeAttribute', 'Bookmark', 'Setting', 'Usergroup', 'HostConfigGroup', 'Template', 'ConfigGroup') OR "audits"."auditable_type" IN ('Medium', 'Parameter', 'JobTemplate', 'Role', 'AuthSource', 'SmartProxy', 'Ptable', 'Hostgroup', 'ComputeResource', 'Host::Base', 'Filter', 'Subnet', 'Domain', 'ProvisioningTemplate', 'User') AND (audits.id IN (5176160,5176161,5176162,5176163,5176164,5176167,5176168,5176165,5176166))) OR "audits"."auditable_type" IN ('Location', 'Katello::SyncPlan') AND (audits.id IN (5176160,5176161,5176162,5176163,5176164,5176167,5176168,5176165,5176166))) OR "audits"."auditable_type" = 'Organization') ORDER BY "audits"."created_at" DESC NULLS LAST LIMIT $1 OFFSET $2; Takes 4.5/40s (DB time) From: /usr/share/foreman/app/views/audits/_list.html.erb:1:in `_0e5da1a8c032ede643628c1674feeb96' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/template.rb:157:in `block in render' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications.rb:168:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/template.rb:352:in `instrument_render_template' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/template.rb:155:in `render' /opt/theforeman/tfm/root/usr/share/gems/gems/deface-1.2.0/lib/deface/action_view_extensions.rb:41:in `render' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/partial_renderer.rb:342:in `block in render_partial' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/abstract_renderer.rb:42:in `block in instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `block in instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/abstract_renderer.rb:41:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/partial_renderer.rb:331:in `render_partial' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/partial_renderer.rb:310:in `render' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/renderer.rb:47:in `render_partial' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/renderer/renderer.rb:21:in `render' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/helpers/rendering_helper.rb:32:in `render' /usr/share/foreman/app/views/audits/index.html.erb:4:in `_e42400f78567dab83fe18299a1a4ee00' This is the actual query that should remain even after the refactorings. Its Ruby times are not big too, since it starts from 31-st second out of 40.
Created redmine issue https://projects.theforeman.org/issues/26760 from this bug
Upstream bug assigned to oprazak
Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/26760 has been resolved.
VERIFIED on sat6.7.0 snap #15 - Verified using the regression tests only - I tried to list all () audits using API $ time curl -sku admin:changeme https://<satfqdn>/api/v2/audits?per_page=30 { "total": 8469, "subtotal": 8469, "page": 1, "per_page": 30, "search": null, "sort": { "by": null, "order": null }, "results": ... } real 0m4.715s user 0m0.045s sys 0m0.018s
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHSA-2020:1454