Red Hat Bugzilla – Bug 1171173
Too many queries to list products - Satellite 6 - Slow Response Time
Last modified: 2017-02-23 15:44:56 EST
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.
Created attachment 965124 [details] debug output from foreman in production.log when browsing UI to list products.
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.
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;
Created redmine issue http://projects.theforeman.org/issues/8954 from this bug
Moving to POST since upstream bug http://projects.theforeman.org/issues/8954 has been closed ------------- Justin Sherrill Applied in changeset commit:katello|11eea88663ef47def9d0254a01ac07463dc24b09.
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.
*** Bug 1221690 has been marked as a duplicate of this bug. ***
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.
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
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
Downstream PR: https://gitlab.sat.lab.tlv.redhat.com/satellite6/katello/merge_requests/87
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.
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
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