Bug 1717194 - [6.4 only] upgrades: improve Katello::Pool.import_all by querying candlepin activation keys once per each org only
Summary: [6.4 only] upgrades: improve Katello::Pool.import_all by querying candlepin a...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Activation Keys
Version: 6.4
Hardware: x86_64
OS: Linux
urgent
unspecified vote
Target Milestone: 6.5.0
Assignee: Partha Aji
QA Contact: Perry Gagne
URL:
Whiteboard:
: 1717703 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-04 20:59 UTC by Mike McCune
Modified: 2019-11-05 22:48 UTC (History)
5 users (show)

Fixed In Version: tfm-rubygem-katello-3.7.0.57-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1683687
: 1717703 (view as bug list)
Environment:
Last Closed: 2019-07-15 15:10:26 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Foreman Issue Tracker 26365 Normal Closed Katello::Pool.import_all unnecessarily slow 2020-04-07 23:42:45 UTC
Red Hat Product Errata RHBA-2019:1780 None None None 2019-07-15 15:10:30 UTC
Red Hat Product Errata RHSA-2019:1222 None None None 2019-06-04 20:59:26 UTC

Description Mike McCune 2019-06-04 20:59:20 UTC
+++ This bug was initially created as a clone of Bug #1683687 +++

Description of problem:
On a scaled environment with thousands of pools, katello:import_subscriptions (called e.g. during an upgrade) does call

Katello::Pool.import_all

that traverses over each and every pool and imports hosts and namely Activation Keys from candlepin. That means, a call like:

/candlepin/owners/RedHat/activation_keys/?include=id&include=pools.pool.id

is repeatedly requested for each and every pool.

If such a request takes longer, overall upgrade time is redundantly increased.

I propose a simple patch to query that once and pass the keys to the proper routine.


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


How reproducible:
100%


Steps to Reproduce:
1. Have a system with some AKs and more pools in manifest - the more the better.

2. in one terminal:
tail -f /var/log/candlepin/candlepin.log | grep "/activation_keys/?include=id&include=pools.pool.id"

3. in 2nd terminal:
foreman-rake katello:import_subscriptions

4. count number of lines printed in the 1st terminal


Actual results:
4. shows as many logs / queries to candlepin as the number of pools is (plus one, I think).


Expected results:
4. to show just 1 or 2 such queries



Additional info:
Patch:

--- /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.46/app/models/katello/glue/candlepin/candlepin_object.rb.orig	2019-02-27 15:43:28.390609472 +0100
+++ /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.46/app/models/katello/glue/candlepin/candlepin_object.rb.new	2019-02-27 15:44:07.067642277 +0100
@@ -37,12 +37,13 @@ module Katello
 
         organizations.each do |org|
           candlepin_ids = import_candlepin_ids(org)
+          keys = Resources::Candlepin::ActivationKey.get(nil, "?include=id&include=pools.pool.id", org.label)
 
           objects = self.in_organization(org)
           objects.each do |item|
             if candlepin_ids.include?(item.cp_id)
               item.import_data
-              item.import_managed_associations if import_managed_associations && item.respond_to?(:import_managed_associations)
+              item.import_managed_associations(keys) if import_managed_associations && item.respond_to?(:import_managed_associations)
             else
               item.destroy
             end

--- /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.46/app/models/katello/glue/candlepin/pool.rb.orig	2019-02-27 15:44:38.758669157 +0100
+++ /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.46/app/models/katello/glue/candlepin/pool.rb.new 	2019-02-27 15:50:58.411991079 +0100
@@ -181,17 +181,16 @@ module Katello
         Katello::SubscriptionFacetPool.where(:pool_id => self.id, :subscription_facet_id => entries_to_remove).delete_all
       end
 
-      def import_managed_associations
+      def import_managed_associations(keys)
         import_hosts
-        create_activation_key_associations
+        create_activation_key_associations(keys)
       end
 
       def hosts
         ::Host.where(:id => self.subscription_facets.pluck(:host_id))
       end
 
-      def create_activation_key_associations
-        keys = Resources::Candlepin::ActivationKey.get(nil, "?include=id&include=pools.pool.id", organization.label)
+      def create_activation_key_associations(keys)
         activation_key_ids = keys.collect do |key|
           key['id'] if key['pools'].present? && key['pools'].any? { |pool| pool['pool'].try(:[], 'id') == cp_id }
         end

--- Additional comment from  on 2019-02-27T15:00:53Z 

Since this bug report was entered in Red Hat Bugzilla, the 'sat-backlog' flag has been set to ? to ensure that it is properly evaluated for release.

--- Additional comment from  on 2019-02-27T15:00:53Z 

Since this issue was entered in Red Hat Bugzilla, the pm_ack has been set to + automatically for the next planned release.

--- Additional comment from  on 2019-02-27T15:06:07Z 

Re number of such queries after the patch: there should be as many as the number of organizations is (plus one), not "just" 1-2. But still significantly less than # of pools.

--- Additional comment from  on 2019-02-27T15:14:45Z 

This bugfix can be critical for Credit Suisse where 6.3->6.4 upgrade takes 3+ days only due to this inefficiency (together with fact candlepin responds to one such query in 90s).

--- Additional comment from  on 2019-03-14T16:19:08Z 

Assigning since it has been picked up on our board.

--- Additional comment from  on 2019-03-14T18:21:12Z 

Connecting redmine issue https://projects.theforeman.org/issues/26365 from this bug

--- Additional comment from  on 2019-03-16T02:07:52Z 

Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/26365 has been resolved.

--- Additional comment from  on 2019-03-19T09:47:07Z 

build status: succeeded

brew:
 * tfm-rubygem-katello: closed - https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=20660359

--- Additional comment from  on 2019-03-28T19:50:57Z 

Verified fix in Sat 6.5 snap 21

I created ~3000 custom products to cause pools to be created, and was able to reproduce the issue in a older version. 


The fix was to cache the result on the katello side, with a 2 minute timeout. With PoolTestOrg having ~3000 pools it only needed to call it once 

[root@ibm-x3250m4-04 ~]# tail -f /var/log/candlepin/candlepin.log | grep "/activation_keys/?include=id&include=pools.pool.id"
2019-03-28 15:43:22,424 [thread=http-bio-8443-exec-6] [req=553561f1-0344-458b-8b1f-3501df9e536f, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/Default_Organization/activation_keys/?include=id&include=pools.pool.id
2019-03-28 15:43:22,650 [thread=http-bio-8443-exec-5] [req=0602e7e9-65b2-451c-b9d8-0b17ec332f01, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/mJzBcX/activation_keys/?include=id&include=pools.pool.id
2019-03-28 15:43:29,287 [thread=http-bio-8443-exec-8] [req=d4df87d0-1452-4d5a-97bb-9660c8672ed3, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/PoolTestOrg/activation_keys/?include=id&include=pools.pool.id
2019-03-28 15:45:21,533 [thread=http-bio-8443-exec-9] [req=8f442b6a-99e3-4bee-92d9-fa8478768d6b, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/stagetest1/activation_keys/?include=id&include=pools.pool.id
2019-03-28 15:45:21,694 [thread=http-bio-8443-exec-2] [req=3afec1df-562f-46fe-bed1-f9eaaf51e821, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/vMIQAzD/activation_keys/?include=id&include=pools.pool.id

--- Additional comment from  on 2019-05-14T00:16:56Z 

Bug report changed to RELEASE_PENDING status by Errata System.
Advisory RHSA-2019:40972-08 has been changed to PUSH_READY status.
https://errata.devel.redhat.com/advisory/40972

--- Additional comment from  on 2019-05-14T00:16:57Z 

Bug report changed to RELEASE_PENDING status by Errata System.
Advisory RHSA-2019:40972-08 has been changed to PUSH_READY status.
https://errata.devel.redhat.com/advisory/40972

--- Additional comment from  on 2019-05-14T12:40:17Z 

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-2019:1222

Comment 3 Mike McCune 2019-06-04 21:14:12 UTC
This performance improvement has reduced this step during upgrades on large customers by large orders of magnitude:


Upgrade Step: set_upstream_pool_id (this may take a while) ...

BEFORE: 5-9 hour execution time
AFTER: 5-10 minute execution time

Comment 5 Mike McCune 2019-06-05 23:41:44 UTC
*** Bug 1717703 has been marked as a duplicate of this bug. ***

Comment 7 Perry Gagne 2019-07-02 14:12:12 UTC
Verified fix in 6.4.4 snap 3. With steps from bz 1683687

1. Created PoolTestOrg. 
2. Created 3000 products with repos (all pointing to the same URL).
3. Created 5 activation keys 
4. Ran 'time foreman-rake katello:import_subscriptions' and 'tail -f /var/log/candlepin/candlepin.log | grep "/activation_keys/?include=id&include=pools.pool.id""

The "import subscriptions" call took about 3m 20 seconds

[root@sat ~]# time foreman-rake katello:import_subscriptions
/usr/share/foreman/lib/foreman.rb:8: warning: already initialized constant Foreman::UUID_REGEXP
/usr/share/foreman/lib/foreman.rb:8: warning: previous definition of UUID_REGEXP was here
/usr/share/foreman/lib/core_extensions.rb:182: warning: already initialized constant ActiveSupport::MessageEncryptor::DEFAULT_CIPHER
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/message_encryptor.rb:22: warning: previous definition of DEFAULT_CIPHER was here
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/content_facet_host_extensions.rb:7: warning: already initialized constant Katello::Concerns::ContentFacetHostExtensions::ERRATA_STATUS_MAP
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/content_facet_host_extensions.rb:7: warning: previous definition of ERRATA_STATUS_MAP was here
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/content_facet_host_extensions.rb:14: warning: already initialized constant Katello::Concerns::ContentFacetHostExtensions::TRACE_STATUS_MAP
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/content_facet_host_extensions.rb:14: warning: previous definition of TRACE_STATUS_MAP was here
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/subscription_facet_host_extensions.rb:13: warning: already initialized constant Katello::Concerns::SubscriptionFacetHostExtensions::SUBSCRIPTION_STATUS_MAP
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.58/app/models/katello/concerns/subscription_facet_host_extensions.rb:13: warning: previous definition of SUBSCRIPTION_STATUS_MAP was here
Importing Subscriptions

real	3m20.399s
user	1m54.030s
sys	0m8.031s

The API Request only occurred once: 

[root@ibm-x3250m4-02 ~]# tail -f /var/log/candlepin/candlepin.log | grep "/activation_keys/?include=id&include=pools.pool.id"
2019-07-02 09:59:43,023 [thread=http-bio-8443-exec-7] [req=5eda4188-602d-4f19-ac3c-c568956bcea0, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/Default_Organization/activation_keys/?include=id&include=pools.pool.id
2019-07-02 09:59:49,392 [thread=http-bio-8443-exec-4] [req=c191728e-4fab-4308-888c-1acd63fc67c3, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/owners/PoolTestOrg/activation_keys/?include=id&include=pools.pool.id

Comment 9 errata-xmlrpc 2019-07-15 15:10:26 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/RHBA-2019:1780


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