Bug 1703490

Summary: Satelllite Audits page is very slow
Product: Red Hat Satellite Reporter: sthirugn <sthirugn>
Component: Audit LogAssignee: Ondřej Pražák <oprazak>
Status: CLOSED ERRATA QA Contact: Roman Plevka <rplevka>
Severity: medium Docs Contact:
Priority: high    
Version: 6.4.2CC: andrew.schofield, christian.klier, inecas, kgaikwad, pcreech, rplevka, sshtein
Target Milestone: 6.7.0Keywords: Performance, Triaged, UserExperience
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-04-14 13:24:30 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:
Description Flags
production.log
none
postgrsql log none

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