Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1515093 - slow query logged: duration: 1004.645 ms execute <unnamed>: select entitlemen0_.pool_id as pool_id10_36_0_...
Summary: slow query logged: duration: 1004.645 ms execute <unnamed>: select entitleme...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Candlepin
Version: 6.3.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium vote
Target Milestone: Unspecified
Assignee: Alex Wood
QA Contact: Jan Hutař
URL:
Whiteboard: scale_lab
Depends On: 1517848
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-20 06:58 UTC by Jan Hutař
Modified: 2019-04-01 20:27 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1517848 (view as bug list)
Environment:
Last Closed: 2018-10-16 19:25:10 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Github candlepin candlepin pull 1830 None None None 2017-12-01 21:20:17 UTC

Description Jan Hutař 2017-11-20 06:58:46 UTC
Description of problem:
I'm running 30 concurrent registrations using bootstrap.py for 22 hours, so Satellite have almost 9k registered content hosts now, but noticed this slow PostgreSQL query being logged (have "log_min_duration_statement = 1000" in the DB config).


Version-Release number of selected component (if applicable):
satellite-6.3.0-21.0.beta.el7sat.noarch


How reproducible:
Every +- 10 minutes


Steps to Reproduce:
1. Run 30 concurrent registrations (on different systems every time) for
   22 hours
2. Set "log_min_duration_statement = 1000" and watch the PostgreSQL logs


Actual results:
2017-11-19 23:52:29 EST LOG:  duration: 1004.645 ms  execute <unnamed>: select entitlemen0_.pool_id as pool_id10_36_0_, entitlemen0_.id as id1_36_0_, entitlemen0_.id as id1_36_1_, entitlemen0_.created as created2_36_1_, entitlemen0_.updated as updated3_36_1_, entitlemen0_.consumer_id as consumer8_36_1_, entitlemen0_.dirty as dirty4_36_1_, entitlemen0_.endDateOverride as endDateO5_36_1_, entitlemen0_.owner_id as owner_id9_36_1_, entitlemen0_.pool_id as pool_id10_36_1_, entitlemen0_.quantity as quantity6_36_1_, entitlemen0_.updatedOnStart as updatedO7_36_1_, consumer1_.id as id1_22_2_, consumer1_.created as created2_22_2_, consumer1_.updated as updated3_22_2_, consumer1_.annotations as annotati4_22_2_, consumer1_.autoheal as autoheal5_22_2_, consumer1_.complianceStatusHash as complian6_22_2_, consumer1_.cont_acc_cert_id as cont_ac17_22_2_, consumer1_.content_access_mode as content_7_22_2_, consumer1_.entitlement_count as entitlem8_22_2_, consumer1_.entitlementStatus as entitlem9_22_2_, consumer1_.environment_id as environ18_22_2_, consumer1_.consumer_idcert_id as consume19_22_2_, consumer1_.keyPair_id as keyPair20_22_2_, consumer1_.lastCheckin as lastChe10_22_2_, consumer1_.name as name11_22_2_, consumer1_.owner_id as owner_i21_22_2_, consumer1_.recipient_owner_key as recipie12_22_2_, consumer1_.releaseVer as release13_22_2_, consumer1_.serviceLevel as service14_22_2_, consumer1_.type_id as type_id22_22_2_, consumer1_.username as usernam15_22_2_, consumer1_.uuid as uuid16_22_2_, environmen2_.id as id1_37_3_, environmen2_.created as created2_37_3_, environmen2_.updated as updated3_37_3_, environmen2_.description as descript4_37_3_, environmen2_.name as name5_37_3_, environmen2_.owner_id as owner_id6_37_3_, owner3_.id as id1_47_4_, owner3_.created as created2_47_4_, owner3_.updated as updated3_47_4_, owner3_.autobind_disabled as autobind4_47_4_, owner3_.content_access_mode as content_5_47_4_, owner3_.content_access_mode_list as content_6_47_4_, owner3_.contentPrefix as contentP7_47_4_, owner3_.defaultServiceLevel as defaultS8_47_4_, owner3_.displayName as displayN9_47_4_, owner3_.account as account10_47_4_, owner3_.logLevel as logLeve11_47_4_, owner3_.parent_owner as parent_12_47_4_, owner3_.upstream_id as upstrea13_47_4_, owner4_.id as id1_47_5_, owner4_.created as created2_47_5_, owner4_.updated as updated3_47_5_, owner4_.autobind_disabled as autobind4_47_5_, owner4_.content_access_mode as content_5_47_5_, owner4_.content_access_mode_list as content_6_47_5_, owner4_.contentPrefix as contentP7_47_5_, owner4_.defaultServiceLevel as defaultS8_47_5_, owner4_.displayName as displayN9_47_5_, owner4_.account as account10_47_5_, owner4_.logLevel as logLeve11_47_5_, owner4_.parent_owner as parent_12_47_5_, owner4_.upstream_id as upstrea13_47_5_, identityce5_.id as id1_40_6_, identityce5_.created as created2_40_6_, identityce5_.updated as updated3_40_6_, identityce5_.cert as cert4_40_6_, identityce5_.privatekey as privatek5_40_6_, identityce5_.serial_id as serial_i6_40_6_, certificat6_.id as id1_20_7_, certificat6_.created as created2_20_7_, certificat6_.updated as updated3_20_7_, certificat6_.collected as collecte4_20_7_, certificat6_.expiration as expirati5_20_7_, certificat6_.revoked as revoked6_20_7_, keypair7_.id as id1_45_8_, keypair7_.created as created2_45_8_, keypair7_.updated as updated3_45_8_, keypair7_.privateKey as privateK4_45_8_, keypair7_.publicKey as publicKe5_45_8_, owner8_.id as id1_47_9_, owner8_.created as created2_47_9_, owner8_.updated as updated3_47_9_, owner8_.autobind_disabled as autobind4_47_9_, owner8_.content_access_mode as content_5_47_9_, owner8_.content_access_mode_list as content_6_47_9_, owner8_.contentPrefix as contentP7_47_9_, owner8_.defaultServiceLevel as defaultS8_47_9_, owner8_.displayName as displayN9_47_9_, owner8_.account as account10_47_9_, owner8_.logLevel as logLeve11_47_9_, owner8_.parent_owner as parent_12_47_9_, owner8_.upstream_id as upstrea13_47_9_, consumerty9_.id as id1_29_10_, consumerty9_.created as created2_29_10_, consumerty9_.updated as updated3_29_10_, consumerty9_.label as label4_29_10_, consumerty9_.manifest as manifest5_29_10_, hypervisor10_.id as id1_28_11_, hypervisor10_.created as created2_28_11_, hypervisor10_.updated as updated3_28_11_, hypervisor10_.consumer_id as consumer6_28_11_, hypervisor10_.hypervisor_id as hypervis4_28_11_, hypervisor10_.owner_id as owner_id7_28_11_, hypervisor10_.reporter_id as reporter5_28_11_, owner11_.id as id1_47_12_, owner11_.created as created2_47_12_, owner11_.updated as updated3_47_12_, owner11_.autobind_disabled as autobind4_47_12_, owner11_.content_access_mode as content_5_47_12_, owner11_.content_access_mode_list as content_6_47_12_, owner11_.contentPrefix as contentP7_47_12_, owner11_.defaultServiceLevel as defaultS8_47_12_, owner11_.displayName as displayN9_47_12_, owner11_.account as account10_47_12_, owner11_.logLevel as logLeve11_47_12_, owner11_.parent_owner as parent_12_47_12_, owner11_.upstream_id as upstrea13_47_12_ from cp_entitlement entitlemen0_ inner join cp_consumer consumer1_ on entitlemen0_.consumer_id=consumer1_.id left outer join cp_environment environmen2_ on consumer1_.environment_id=environmen2_.id left outer join cp_owner owner3_ on environmen2_.owner_id=owner3_.id left outer join cp_owner owner4_ on owner3_.parent_owner=owner4_.id left outer join cp_id_cert identityce5_ on consumer1_.consumer_idcert_id=identityce5_.id left outer join cp_cert_serial certificat6_ on identityce5_.serial_id=certificat6_.id left outer join cp_key_pair keypair7_ on consumer1_.keyPair_id=keypair7_.id inner join cp_owner owner8_ on consumer1_.owner_id=owner8_.id inner join cp_consumer_type consumerty9_ on consumer1_.type_id=consumerty9_.id left outer join cp_consumer_hypervisor hypervisor10_ on consumer1_.id=hypervisor10_.consumer_id inner join cp_owner owner11_ on entitlemen0_.owner_id=owner11_.id where entitlemen0_.pool_id=$1
2017-11-19 23:52:29 EST DETAIL:  parameters: $1 = '2c9280815fbcc57c015fbf17105e22be'


Expected results:
Having query taking this long suggests there might be something sub-optimal somewhere.

Comment 1 Jan Hutař 2017-11-20 06:59:03 UTC
candlepin=# EXPLAIN ANALYZE select entitlemen0_.pool_id as pool_id10_36_0_, entitlemen0_.id as id1_36_0_, entitlemen0_.id as id1_36_1_, entitlemen0_.created as created2_36_1_, entitlemen0_.updated as updated3_36_1_, entitlemen0_.consumer_id as consumer8_36_1_, entitlemen0_.dirty as dirty4_36_1_, entitlemen0_.endDateOverride as endDateO5_36_1_, entitlemen0_.owner_id as owner_id9_36_1_, entitlemen0_.pool_id as pool_id10_36_1_, entitlemen0_.quantity as quantity6_36_1_, entitlemen0_.updatedOnStart as updatedO7_36_1_, consumer1_.id as id1_22_2_, consumer1_.created as created2_22_2_, consumer1_.updated as updated3_22_2_, consumer1_.annotations as annotati4_22_2_, consumer1_.autoheal as autoheal5_22_2_, consumer1_.complianceStatusHash as complian6_22_2_, consumer1_.cont_acc_cert_id as cont_ac17_22_2_, consumer1_.content_access_mode as content_7_22_2_, consumer1_.entitlement_count as entitlem8_22_2_, consumer1_.entitlementStatus as entitlem9_22_2_, consumer1_.environment_id as environ18_22_2_, consumer1_.consumer_idcert_id as consume19_22_2_, consumer1_.keyPair_id as keyPair20_22_2_, consumer1_.lastCheckin as lastChe10_22_2_, consumer1_.name as name11_22_2_, consumer1_.owner_id as owner_i21_22_2_, consumer1_.recipient_owner_key as recipie12_22_2_, consumer1_.releaseVer as release13_22_2_, consumer1_.serviceLevel as service14_22_2_, consumer1_.type_id as type_id22_22_2_, consumer1_.username as usernam15_22_2_, consumer1_.uuid as uuid16_22_2_, environmen2_.id as id1_37_3_, environmen2_.created as created2_37_3_, environmen2_.updated as updated3_37_3_, environmen2_.description as descript4_37_3_, environmen2_.name as name5_37_3_, environmen2_.owner_id as owner_id6_37_3_, owner3_.id as id1_47_4_, owner3_.created as created2_47_4_, owner3_.updated as updated3_47_4_, owner3_.autobind_disabled as autobind4_47_4_, owner3_.content_access_mode as content_5_47_4_, owner3_.content_access_mode_list as content_6_47_4_, owner3_.contentPrefix as contentP7_47_4_, owner3_.defaultServiceLevel as defaultS8_47_4_, owner3_.displayName as displayN9_47_4_, owner3_.account as account10_47_4_, owner3_.logLevel as logLeve11_47_4_, owner3_.parent_owner as parent_12_47_4_, owner3_.upstream_id as upstrea13_47_4_, owner4_.id as id1_47_5_, owner4_.created as created2_47_5_, owner4_.updated as updated3_47_5_, owner4_.autobind_disabled as autobind4_47_5_, owner4_.content_access_mode as content_5_47_5_, owner4_.content_access_mode_list as content_6_47_5_, owner4_.contentPrefix as contentP7_47_5_, owner4_.defaultServiceLevel as defaultS8_47_5_, owner4_.displayName as displayN9_47_5_, owner4_.account as account10_47_5_, owner4_.logLevel as logLeve11_47_5_, owner4_.parent_owner as parent_12_47_5_, owner4_.upstream_id as upstrea13_47_5_, identityce5_.id as id1_40_6_, identityce5_.created as created2_40_6_, identityce5_.updated as updated3_40_6_, identityce5_.cert as cert4_40_6_, identityce5_.privatekey as privatek5_40_6_, identityce5_.serial_id as serial_i6_40_6_, certificat6_.id as id1_20_7_, certificat6_.created as created2_20_7_, certificat6_.updated as updated3_20_7_, certificat6_.collected as collecte4_20_7_, certificat6_.expiration as expirati5_20_7_, certificat6_.revoked as revoked6_20_7_, keypair7_.id as id1_45_8_, keypair7_.created as created2_45_8_, keypair7_.updated as updated3_45_8_, keypair7_.privateKey as privateK4_45_8_, keypair7_.publicKey as publicKe5_45_8_, owner8_.id as id1_47_9_, owner8_.created as created2_47_9_, owner8_.updated as updated3_47_9_, owner8_.autobind_disabled as autobind4_47_9_, owner8_.content_access_mode as content_5_47_9_, owner8_.content_access_mode_list as content_6_47_9_, owner8_.contentPrefix as contentP7_47_9_, owner8_.defaultServiceLevel as defaultS8_47_9_, owner8_.displayName as displayN9_47_9_, owner8_.account as account10_47_9_, owner8_.logLevel as logLeve11_47_9_, owner8_.parent_owner as parent_12_47_9_, owner8_.upstream_id as upstrea13_47_9_, consumerty9_.id as id1_29_10_, consumerty9_.created as created2_29_10_, consumerty9_.updated as updated3_29_10_, consumerty9_.label as label4_29_10_, consumerty9_.manifest as manifest5_29_10_, hypervisor10_.id as id1_28_11_, hypervisor10_.created as created2_28_11_, hypervisor10_.updated as updated3_28_11_, hypervisor10_.consumer_id as consumer6_28_11_, hypervisor10_.hypervisor_id as hypervis4_28_11_, hypervisor10_.owner_id as owner_id7_28_11_, hypervisor10_.reporter_id as reporter5_28_11_, owner11_.id as id1_47_12_, owner11_.created as created2_47_12_, owner11_.updated as updated3_47_12_, owner11_.autobind_disabled as autobind4_47_12_, owner11_.content_access_mode as content_5_47_12_, owner11_.content_access_mode_list as content_6_47_12_, owner11_.contentPrefix as contentP7_47_12_, owner11_.defaultServiceLevel as defaultS8_47_12_, owner11_.displayName as displayN9_47_12_, owner11_.account as account10_47_12_, owner11_.logLevel as logLeve11_47_12_, owner11_.parent_owner as parent_12_47_12_, owner11_.upstream_id as upstrea13_47_12_ from cp_entitlement entitlemen0_ inner join cp_consumer consumer1_ on entitlemen0_.consumer_id=consumer1_.id left outer join cp_environment environmen2_ on consumer1_.environment_id=environmen2_.id left outer join cp_owner owner3_ on environmen2_.owner_id=owner3_.id left outer join cp_owner owner4_ on owner3_.parent_owner=owner4_.id left outer join cp_id_cert identityce5_ on consumer1_.consumer_idcert_id=identityce5_.id left outer join cp_cert_serial certificat6_ on identityce5_.serial_id=certificat6_.id left outer join cp_key_pair keypair7_ on consumer1_.keyPair_id=keypair7_.id inner join cp_owner owner8_ on consumer1_.owner_id=owner8_.id inner join cp_consumer_type consumerty9_ on consumer1_.type_id=consumerty9_.id left outer join cp_consumer_hypervisor hypervisor10_ on consumer1_.id=hypervisor10_.consumer_id inner join cp_owner owner11_ on entitlemen0_.owner_id=owner11_.id where entitlemen0_.pool_id='2c9280815fbcc57c015fbf17105e22be';
                                                                                                             QUERY PLAN                                                                                                             
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Hash Join  (cost=77.47..24574.05 rows=9014 width=21459) (actual time=0.453..523.035 rows=9004 loops=1)
   Hash Cond: ((entitlemen0_.owner_id)::text = (owner11_.id)::text)
   ->  Hash Left Join  (cost=67.02..24439.66 rows=9014 width=18018) (actual time=0.439..515.535 rows=9004 loops=1)
         Hash Cond: ((consumer1_.id)::text = (hypervisor10_.consumer_id)::text)
         ->  Hash Join  (cost=55.67..24393.92 rows=9014 width=16724) (actual time=0.428..509.685 rows=9004 loops=1)
               Hash Cond: ((consumer1_.type_id)::text = (consumerty9_.id)::text)
               ->  Hash Join  (cost=42.97..24257.28 rows=9014 width=16102) (actual time=0.415..502.793 rows=9004 loops=1)
                     Hash Cond: ((consumer1_.owner_id)::text = (owner8_.id)::text)
                     ->  Nested Loop Left Join  (cost=32.52..24122.88 rows=9014 width=12661) (actual time=0.403..495.813 rows=9004 loops=1)
                           ->  Nested Loop Left Join  (cost=32.52..16989.92 rows=9014 width=12039) (actual time=0.380..323.326 rows=9004 loops=1)
                                 ->  Hash Left Join  (cost=32.52..11406.89 rows=9014 width=12005) (actual time=0.332..289.081 rows=9004 loops=1)
                                       Hash Cond: ((environmen2_.owner_id)::text = (owner3_.id)::text)
                                       ->  Hash Left Join  (cost=11.35..11321.86 rows=9014 width=5123) (actual time=0.303..281.810 rows=9004 loops=1)
                                             Hash Cond: ((consumer1_.environment_id)::text = (environmen2_.id)::text)
                                             ->  Merge Left Join  (cost=0.00..11186.57 rows=9014 width=3911) (actual time=0.268..276.290 rows=9004 loops=1)
                                                   Merge Cond: ((consumer1_.consumer_idcert_id)::text = (identityce5_.id)::text)
                                                   ->  Nested Loop  (cost=0.00..7533.16 rows=9014 width=2156) (actual time=0.167..202.773 rows=9004 loops=1)
                                                         ->  Index Scan using cp_consumer_consumer_idcert_id_idx on cp_consumer consumer1_  (cost=0.00..1384.96 rows=9199 width=1994) (actual time=0.003..13.080 rows=9014 loops=1)
                                                         ->  Index Scan using cp_entitlement_consumer_id_idx on cp_entitlement entitlemen0_  (cost=0.00..0.66 rows=1 width=162) (actual time=0.020..0.020 rows=1 loops=9014)
                                                               Index Cond: ((consumer_id)::text = (consumer1_.id)::text)
                                                               Filter: ((pool_id)::text = '2c9280815fbcc57c015fbf17105e22be'::text)
                                                               Rows Removed by Filter: 1
                                                   ->  Index Scan using cp_id_cert_pkey on cp_id_cert identityce5_  (cost=0.00..3519.99 rows=9015 width=1755) (actual time=0.002..22.415 rows=9024 loops=1)
                                             ->  Hash  (cost=10.60..10.60 rows=60 width=1212) (actual time=0.015..0.015 rows=2 loops=1)
                                                   Buckets: 1024  Batches: 1  Memory Usage: 1kB
                                                   ->  Seq Scan on cp_environment environmen2_  (cost=0.00..10.60 rows=60 width=1212) (actual time=0.013..0.013 rows=2 loops=1)
                                       ->  Hash  (cost=20.92..20.92 rows=20 width=6882) (actual time=0.020..0.020 rows=1 loops=1)
                                             Buckets: 1024  Batches: 1  Memory Usage: 1kB
                                             ->  Hash Left Join  (cost=10.45..20.92 rows=20 width=6882) (actual time=0.019..0.020 rows=1 loops=1)
                                                   Hash Cond: ((owner3_.parent_owner)::text = (owner4_.id)::text)
                                                   ->  Seq Scan on cp_owner owner3_  (cost=0.00..10.20 rows=20 width=3441) (actual time=0.001..0.002 rows=1 loops=1)
                                                   ->  Hash  (cost=10.20..10.20 rows=20 width=3441) (actual time=0.002..0.002 rows=1 loops=1)
                                                         Buckets: 1024  Batches: 1  Memory Usage: 1kB
                                                         ->  Seq Scan on cp_owner owner4_  (cost=0.00..10.20 rows=20 width=3441) (actual time=0.001..0.001 rows=1 loops=1)
                                 ->  Index Scan using cp_cert_serial_pkey on cp_cert_serial certificat6_  (cost=0.00..0.61 rows=1 width=34) (actual time=0.003..0.003 rows=1 loops=9004)
                                       Index Cond: (identityce5_.serial_id = id)
                           ->  Index Scan using cp_key_pair_pkey on cp_key_pair keypair7_  (cost=0.00..0.78 rows=1 width=622) (actual time=0.018..0.018 rows=1 loops=9004)
                                 Index Cond: ((consumer1_.keypair_id)::text = (id)::text)
                     ->  Hash  (cost=10.20..10.20 rows=20 width=3441) (actual time=0.002..0.002 rows=1 loops=1)
                           Buckets: 1024  Batches: 1  Memory Usage: 1kB
                           ->  Seq Scan on cp_owner owner8_  (cost=0.00..10.20 rows=20 width=3441) (actual time=0.001..0.001 rows=1 loops=1)
               ->  Hash  (cost=11.20..11.20 rows=120 width=622) (actual time=0.008..0.008 rows=10 loops=1)
                     Buckets: 1024  Batches: 1  Memory Usage: 1kB
                     ->  Seq Scan on cp_consumer_type consumerty9_  (cost=0.00..11.20 rows=120 width=622) (actual time=0.002..0.004 rows=10 loops=1)
         ->  Hash  (cost=10.60..10.60 rows=60 width=1294) (actual time=0.000..0.000 rows=0 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 0kB
               ->  Seq Scan on cp_consumer_hypervisor hypervisor10_  (cost=0.00..10.60 rows=60 width=1294) (actual time=0.000..0.000 rows=0 loops=1)
   ->  Hash  (cost=10.20..10.20 rows=20 width=3441) (actual time=0.008..0.008 rows=1 loops=1)
         Buckets: 1024  Batches: 1  Memory Usage: 1kB
         ->  Seq Scan on cp_owner owner11_  (cost=0.00..10.20 rows=20 width=3441) (actual time=0.003..0.003 rows=1 loops=1)
 Total runtime: 524.493 ms
(51 rows)

Comment 2 Jan Hutař 2017-11-20 13:02:36 UTC
This was actually observed for series of 60 concurrent regs (with 3 retries on failure on client side), not 30 concurrent. I'm sorry for confusion.

Comment 12 Bryan Kearney 2018-10-16 19:25:10 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-2018:2927


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