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 1171173 - Too many queries to list products - Satellite 6 - Slow Response Time
Summary: Too many queries to list products - Satellite 6 - Slow Response Time
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: API
Version: 6.0.4
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: Unspecified
Assignee: Justin Sherrill
QA Contact: Alex Krzos
URL: http://projects.theforeman.org/issues...
Whiteboard:
: 1221690 (view as bug list)
Depends On:
Blocks: 1122832
TreeView+ depends on / blocked
 
Reported: 2014-12-05 15:37 UTC by Alex Krzos
Modified: 2019-07-11 08:25 UTC (History)
13 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-08-12 05:20:20 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
Snippet of foreman production.log with hammer running. (63.93 KB, application/x-gzip)
2014-12-05 15:37 UTC, Alex Krzos 		no flags Details
debug output from foreman in production.log when browsing UI to list products. (64.19 KB, application/x-gzip)
2014-12-05 15:39 UTC, Alex Krzos 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2015:1592 0 normal SHIPPED_LIVE Important: Red Hat Satellite 6.1.1 on RHEL 6 2015-08-12 09:04:35 UTC

Description Alex Krzos 2014-12-05 15:37:17 UTC 
Created attachment 965123 [details]
Snippet of foreman production.log with hammer running.

Description of problem:
When adding many products with many repos, listing the products performs too many queries which creates a slow response time for the API/UI.


Version-Release number of selected component (if applicable):
6.0.4

How reproducible:
Always

Steps to Reproduce:
1. Add 8 custom products
2. Add 21 repos per product
3. Sync repos (Not sure if this is necessary to reproduce)
4. time hammer product list --organization-id 1

Actual results:
# time h product list --organization-id 1
---|---------------------|-------------|----------------------|--------------|-----------
ID | NAME                | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|---------------------|-------------|----------------------|--------------|-----------
2  | perf-gen1           |             | Default_Organization | 21           | finished
5  | perf-gen4           |             | Default_Organization | 21           | finished
8  | perf-gen7           |             | Default_Organization | 21           | finished
3  | perf-gen2           |             | Default_Organization | 21           | finished
6  | perf-gen5           |             | Default_Organization | 21           | finished
9  | perf-gen8           |             | Default_Organization | 21           | finished
1  | perf-puppet-modules |             | Default_Organization | 1            | not_synced
4  | perf-gen3           |             | Default_Organization | 21           | finished
7  | perf-gen6           |             | Default_Organization | 21           | finished
---|---------------------|-------------|----------------------|--------------|-----------

real    0m26.469s
user    0m2.318s
sys     0m0.526s

x 3 more:
0m26.022s
0m26.822s
0m25.895s

Expected results:
<3s to display 8 products, the number of associated repos and whether or not they have been synced.

Additional info:
The issue appears to be rooted with the shear number of queries to list the products:

$ grep -i "select" production-*.log -c
production-hammer.log:2123
production-ui.log:2122
$ grep -i "cache" production-*.log -c
production-hammer.log:1537
production-ui.log:1535

Counting cached queries, we have 2123 queries to perform this.
Comment 1 Alex Krzos 2014-12-05 15:39:33 UTC 
Created attachment 965124 [details]
debug output from foreman in production.log when browsing UI to list products.
Comment 2 RHEL Program Management 2014-12-05 15:45:26 UTC 
Since this issue was entered in Red Hat Bugzilla, the release flag has been
set to ? to ensure that it is properly evaluated for this release.
Comment 4 Justin Sherrill 2015-01-13 18:46:17 UTC 
hammer commands to set this up:

for i in `seq  8`; do 
 hammer -u admin -p changeme product create --name "Product-$i" --organization="Default Organization"
 for j in `seq 21`; do
   hammer -u admin -p changeme repository create --name "Repo-$j" --product "Product-$i"  --organization="Default Organization" --content-type=yum
 done;
done;
Comment 5 Justin Sherrill 2015-01-14 16:52:44 UTC 
Created redmine issue http://projects.theforeman.org/issues/8954 from this bug
Comment 6 Bryan Kearney 2015-02-24 19:04:26 UTC 
Moving to POST since upstream bug http://projects.theforeman.org/issues/8954 has been closed
-------------
Justin Sherrill
Applied in changeset commit:katello|11eea88663ef47def9d0254a01ac07463dc24b09.
Comment 9 Alex Krzos 2015-05-01 15:07:58 UTC 
From hammer/Web UI this is partially fixed.  The timings are better by ~10seconds compared to the original data.  Running against 8 custom products with 21 unsynced repos per product the time is still at around 16s with foreman debug logging.  This was tested on the same hardware with a RHEL 7 Sat 6.1 Build.  

# time hammer -u admin -p changeme product list --organization-id 1
---|-----------|-------------|----------------------|--------------|-----------
ID | NAME      | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|-----------|-------------|----------------------|--------------|-----------
1  | perf-gen1 |             | Default Organization | 21           | not_synced
2  | perf-gen2 |             | Default Organization | 21           | not_synced
3  | perf-gen3 |             | Default Organization | 21           | not_synced
4  | perf-gen4 |             | Default Organization | 21           | not_synced
5  | perf-gen5 |             | Default Organization | 21           | not_synced
6  | perf-gen6 |             | Default Organization | 21           | not_synced
7  | perf-gen7 |             | Default Organization | 21           | not_synced
8  | perf-gen8 |             | Default Organization | 21           | not_synced
---|-----------|-------------|----------------------|--------------|-----------

real    0m16.249s
user    0m0.939s
sys     0m0.067s

x 3 more:
0m16.229s
0m16.047s
0m16.134s

Before adding repos:
# time hammer -u admin -p changeme product list --organization-id 1
---|-----------|-------------|----------------------|--------------|-----------
ID | NAME      | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|-----------|-------------|----------------------|--------------|-----------
1  | perf-gen1 |             | Default Organization | 0            | not_synced
2  | perf-gen2 |             | Default Organization | 0            | not_synced
3  | perf-gen3 |             | Default Organization | 0            | not_synced
4  | perf-gen4 |             | Default Organization | 0            | not_synced
5  | perf-gen5 |             | Default Organization | 0            | not_synced
6  | perf-gen6 |             | Default Organization | 0            | not_synced
7  | perf-gen7 |             | Default Organization | 0            | not_synced
8  | perf-gen8 |             | Default Organization | 0            | not_synced
---|-----------|-------------|----------------------|--------------|-----------

real    0m1.542s
user    0m0.655s
sys     0m0.068s

Web UI timing with repos added:
production.ui.21repos.log:2015-05-01 10:51:06 [I] Completed 200 OK in 16372ms (Views: 16150.6ms | ActiveRecord: 193.5ms)

# of Queries:

$ grep -i "select" production*.log -c
production.hammer.21repos.log:1238
production.hammer.norepos.log:230
production.ui.21repos.log:1428

$ grep -i "cache" production*.log -c
production.hammer.21repos.log:679
production.hammer.norepos.log:176
production.ui.21repos.log:768

* Note the reduction in number of cached queries compared to original data.
Comment 10 Walden Raines 2015-05-15 15:30:44 UTC 
*** Bug 1221690 has been marked as a duplicate of this bug. ***
Comment 11 Mike McCune 2015-05-18 06:15:31 UTC 
IMO, the queries aren't really the issue.

It is the huge number of REST calls into Pulp to fetch sync status.

I have a test org setup with:

50 products with 10 repos each, 400 repos.

To fetch the product list ends up making 1200+ REST calls:

# cd /var/log/httpd
# echo "" > foreman-ssl_access_ssl.log 
# service httpd restart

## ALL Pulp Calls
# grep "GET /pulp" foreman-ssl_access_ssl.log | wc -l
1273

## Just sync status:
# grep "history/sync"  foreman-ssl_access_ssl.log | wc -l
486

This type of IO is *extremely* expensive, way more so than just straight SQL.

We need to either cache this in Katello's DB or skip this data entirely in this API/CLI/UI. It is not worth the performance hit.
Comment 12 Mike McCune 2015-05-18 06:18:07 UTC 
I commented out the code here:

https://github.com/Katello/katello/blob/master/app/models/katello/glue/pulp/repos.rb#L177

to just return:

 return PulpSyncStatus.new(:state => PulpSyncStatus::Status::NOT_SYNCED)

and the hammer command went from 61 seconds to return a value seconds down to 4
Comment 15 Justin Sherrill 2015-07-09 02:53:04 UTC 
Merging these two PRs should address the rest of the performance issues:

https://github.com/Katello/katello/pull/5206
https://github.com/Katello/katello/pull/5234
Comment 16 Justin Sherrill 2015-07-13 17:38:33 UTC 
Downstream PR: https://gitlab.sat.lab.tlv.redhat.com/satellite6/katello/merge_requests/87
Comment 19 Alex Krzos 2015-07-22 19:00:32 UTC 
I am seeing tremendously better results now on Satellite 6.1 - SNAP14 on RHEL7. Average 16s, now down to 1.9-2.1s 87% less time spent.

Timings for 0 products:
# time hammer -u admin -p changeme product list --organization-id 1
---|------|-------------|--------------|--------------|-----------
ID | NAME | DESCRIPTION | ORGANIZATION | REPOSITORIES | SYNC STATE
---|------|-------------|--------------|--------------|-----------

real    0m2.528s
user    0m0.789s
sys     0m0.068s

x 3
real    0m0.932s
real    0m0.919s
real    0m0.975s

Timings for 8 products, 0 repos:
# time hammer -u admin -p changeme product list --organization-id 1
---|-----------|-------------|----------------------|--------------|-----------
ID | NAME      | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|-----------|-------------|----------------------|--------------|-----------
1  | perf-gen1 |             | Default Organization | 0            |
2  | perf-gen2 |             | Default Organization | 0            |
3  | perf-gen3 |             | Default Organization | 0            |
4  | perf-gen4 |             | Default Organization | 0            |
5  | perf-gen5 |             | Default Organization | 0            |
6  | perf-gen6 |             | Default Organization | 0            |
7  | perf-gen7 |             | Default Organization | 0            |
8  | perf-gen8 |             | Default Organization | 0            |
---|-----------|-------------|----------------------|--------------|-----------

real    0m1.390s
user    0m0.742s
sys     0m0.075s

x 3
real    0m1.195s
real    0m1.235s
real    0m1.347s

Timings for 8 products, 24 repos each:
# time hammer -u admin -p changeme product list --organization-id 1
---|-----------|-------------|----------------------|--------------|-----------
ID | NAME      | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|-----------|-------------|----------------------|--------------|-----------
1  | perf-gen1 |             | Default Organization | 21           |
2  | perf-gen2 |             | Default Organization | 21           |
3  | perf-gen3 |             | Default Organization | 21           |
4  | perf-gen4 |             | Default Organization | 21           |
5  | perf-gen5 |             | Default Organization | 21           |
6  | perf-gen6 |             | Default Organization | 21           |
7  | perf-gen7 |             | Default Organization | 21           |
8  | perf-gen8 |             | Default Organization | 21           |
---|-----------|-------------|----------------------|--------------|-----------

real    0m2.148s
user    0m0.803s
sys     0m0.067s

x 3
real    0m1.923s
real    0m2.191s
real    0m1.927s

This was tested on the same host as the original bz was opened on.
Comment 20 Alex Krzos 2015-07-22 20:24:06 UTC 
Timings for 8 products with 21 repos each synced

# time hammer -u admin -p changeme product list --organization-id 1
---|-----------|-------------|----------------------|--------------|------------------
ID | NAME      | DESCRIPTION | ORGANIZATION         | REPOSITORIES | SYNC STATE
---|-----------|-------------|----------------------|--------------|------------------
1  | perf-gen1 |             | Default Organization | 21           | Syncing Complete.
2  | perf-gen2 |             | Default Organization | 21           | Syncing Complete.
3  | perf-gen3 |             | Default Organization | 21           | Syncing Complete.
4  | perf-gen4 |             | Default Organization | 21           | Syncing Complete.
5  | perf-gen5 |             | Default Organization | 21           | Syncing Complete.
6  | perf-gen6 |             | Default Organization | 21           | Syncing Complete.
7  | perf-gen7 |             | Default Organization | 21           | Syncing Complete.
8  | perf-gen8 |             | Default Organization | 21           | Syncing Complete.
---|-----------|-------------|----------------------|--------------|------------------

real	0m8.762s
user	0m0.820s
sys	0m0.122s

x3
real	0m7.488s
real	0m7.530s
real	0m7.455s
Comment 22 errata-xmlrpc 2015-08-12 05:20:20 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-2015:1592
Note You need to log in before you can comment on or make changes to this bug.