Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1703490 - Satelllite Audits page is very slow
Summary: Satelllite Audits page is very slow
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Audit Log
Version: 6.4.2
Hardware: Unspecified
OS: Unspecified
high
medium
Target Milestone: 6.7.0
Assignee: Ondřej Pražák
QA Contact: Roman Plevka
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-04-26 15:07 UTC by sthirugn@redhat.com
Modified: 2024-06-13 22:06 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-04-14 13:24:30 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
production.log (4.65 KB, text/plain)
2019-04-26 15:08 UTC, sthirugn@redhat.com
no flags Details
postgrsql log (4.69 KB, text/plain)
2019-04-26 15:08 UTC, sthirugn@redhat.com
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Foreman Issue Tracker 26760 0 Normal Closed Audits page is very slow 2020-10-27 16:17:10 UTC
Red Hat Product Errata RHSA-2020:1454 0 None None None 2020-04-14 13:24:42 UTC

Description sthirugn@redhat.com 2019-04-26 15:07:25 UTC
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:

Comment 3 sthirugn@redhat.com 2019-04-26 15:08:29 UTC
Created attachment 1559180 [details]
production.log

Comment 4 sthirugn@redhat.com 2019-04-26 15:08:46 UTC
Created attachment 1559181 [details]
postgrsql log

Comment 6 Shimon Shtein 2019-04-30 07:17:40 UTC
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.

Comment 7 Kavita 2019-05-08 09:17:04 UTC
Created redmine issue https://projects.theforeman.org/issues/26760 from this bug

Comment 8 Bryan Kearney 2019-06-24 08:03:45 UTC
Upstream bug assigned to oprazak

Comment 9 Bryan Kearney 2019-06-24 08:03:47 UTC
Upstream bug assigned to oprazak

Comment 10 Bryan Kearney 2019-08-27 12:03:41 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/26760 has been resolved.

Comment 11 Roman Plevka 2020-03-11 12:11:29 UTC
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

Comment 15 errata-xmlrpc 2020-04-14 13:24:30 UTC
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


Note You need to log in before you can comment on or make changes to this bug.