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 1516244 - SQL SELECT from Katello_subscription_facets taking too long to execute (10000ms+)
Summary: SQL SELECT from Katello_subscription_facets taking too long to execute (10000...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Registration
Version: 6.3.0
Hardware: Unspecified
OS: Unspecified
high
urgent vote
Target Milestone: Unspecified
Assignee: Tomer Brisker
QA Contact: jcallaha
URL:
Whiteboard: scale_lab
Depends On:
Blocks: 1437197
TreeView+ depends on / blocked
 
Reported: 2017-11-22 10:59 UTC by sbadhwar
Modified: 2019-04-01 20:27 UTC (History)
12 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-02-21 16:54:17 UTC


Attachments (Terms of Use)
Full query (deleted)
2017-11-27 08:54 UTC, Jan Hutař
no flags Details
`time psql foreman --file /tmp/mine.sql > out2.log` with "EXPLAIN ANALYZE ..." (deleted)
2017-11-27 08:55 UTC, Jan Hutař
no flags Details
`time psql foreman --file /tmp/mine.sql > out3.log` only as "SELECT ..." (deleted)
2017-11-27 08:56 UTC, Jan Hutař
no flags Details


Links
System ID Priority Status Summary Last Updated
Foreman Issue Tracker 21928 None None None 2017-12-11 12:33:52 UTC

Description sbadhwar 2017-11-22 10:59:16 UTC
Description of problem:
While registering 30k content hosts to Satellite, postgresql recorded a slow query which was running for 10,000ms+
x----snip----x
2017-11-22 05:57:45 EST LOG:  duration: 10139.895 ms  execute <unnamed>: SELECT "katello_subscription_facets"."id" FROM "katello_subscription_facets" WHERE "katello_subscription_facets"."uuid" IN ('f371fe1b-fd52-48c0-b93d-f98d867bb976', '984665ea-3d2d-456e-89cb-1635856c7255', '679c7128-91da-46f3-a3d6-c6e7924193ee', '64462ee8-9f37-4ffe-8d4b-688c2f9fac44', '09eb500d-8931-419e-b8c9-3d50e7969836', '5af1e513-7057-43a3-abc2-df240878626f', 'f77bf17b-bf97-4ec2-b676-37dc63a1c386', '739b2ee2-0a69-4641-a745-86a64ba1b371', '1810b5df-5698-4773-9779-fa6520d4fa5f', 'f1a01cb7-79b3-43f0-86b0-d93e1a1e1534', '4b1eda84-e379-4184-b0c4-9bd5bb32e3f8', 'a2b3df33-31e8-439f-9b0b-ea433eb1a6b3', '17c47146-a6c4-4b88-87eb-56261bba55a5', 'a945e6fe-1d73-48e0-87cd-da4b23c2cc79', 'cf0191db-0e93-4363-9e91-0469eab302ef', 'db0ed952-1187-4de1-bd7a-dcf8ff34fe5f', '332df744-2235-4ab5-a217-88d3508d8405', 'f4d36987-da71-49ec-a8d1-1bea2b613704', 'fdc3199a-755b-421d-9afc-a9fab1f3b2f1', 'cf019252-97a5-4bd8-bb72-3da229c0e33b', 'ab8aac77-4d6a-41f8-81ec-00a77766af8b', '4583b375-3e1a-4d9d-9372-3309bcbaf28c', '21a43763-209e-4d21-b64b-285d73164731', '8ef6fbe1-a4a2-4d63-9037-a57b24eb7433', 'b8fee33d-3196-4618-8131-a2867a6889b8', 'fe7b25ec-fc1a-49a0-a8f4-91857c2b58ef', '9229b6cc-17cf-4083-bbf0-6effe67b205d', '432cd848-2ae3-46c8-9175-ede1752eca36', 'ac24e334-6708-4e8d-b7e1-fcdb16028a78', 'f6943295-5388-4b59-a92f-cd1c4285c8bd', 'b4de2388-5895-4d67-b08d-0a7029c1d386', '2a4bd031-777a-4f90-8e0a-1093041d5c81', 'e6c80374-fcb4-4925-bff3-834ac3d45848', 'be394f0a-835c-4a50-8b58-92a08cee5238', 'a04c7417-fa00-46e4-93ab-86959d21dc02', '77002089-ac86-4b85-b026-8abb8db7eabb', '3e65d89c-70a0-4241-ae3a-5fff90c68a8c', 'd0abe560-3931-41c4-8868-e0cfd19d7cd9', '68125942-5ab5-4905-93a0-ba0b001d72ae', '2e08f1ef-d6e0-4dad-a9ac-970829970310', '10deff9a-9d69-4c3e-8acd-d7441cc2000e', '222f0720-89f8-4009-9fe7-fe6680e59bb5', 'de9d794a-35c3-40b0-ae59-da9685e7183c', '7342474c-dfc9-4f9a-b53d-23c248af1230', '7d5bf79d-bfe8-4d78-be99-2604135f6acf', '394c5b2c-f8e0-4758-b4f9-e9c6b1ac9536', '79eb69e7-395d-4594-80da-94630adcc64d', '42a56795-473c-4b8c-8e97-242063344fb5', '1073e487-4e20-400e-9bc7-90873988c894', 'c1d6fc86-903e-4443-b66d-ea2e4a66b8b8', 'be130cf2-65d3-4985-992c-ae3afeae8290', '15af85d7-8191-44de-9bd8-ab9d14e7c1b9', '3f0ff9a5-3......
x----snip----x

Comment 1 sbadhwar 2017-11-22 12:18:02 UTC
So, We tried to run EXPLAIN ANALYZE on the above SQL and seems like the Postgres query planner is running a Sequential Scan for getting the results of the data.

x----snip----x
Seq Scan on katello_subscription_facets  (cost=0.00..1128500.62 rows=18995 width=4) (actual time=0.366..10567.707 rows=29902 loops=1)
x----snip----x

The planner shows a runtime of more than 10s to execute the query which is quite too long for a query to execute and makes it very inefficient.

Comment 2 Chris Duryee 2017-11-26 14:34:02 UTC
If you run this sql against the foreman db, does the issue disappear?

create index test_uuid_idx on katello_subscription_facets(uuid);

Comment 3 Jan Hutař 2017-11-27 08:54:20 UTC
Created attachment 1359361 [details]
Full query

Comment 4 Jan Hutař 2017-11-27 08:55:30 UTC
Created attachment 1359362 [details]
`time psql foreman --file /tmp/mine.sql > out2.log` with "EXPLAIN ANALYZE ..."

-bash-4.2$ time psql foreman --file /tmp/mine.sql > out2.log

real	0m0.505s
user	0m0.089s
sys	0m0.015s

Comment 5 Jan Hutař 2017-11-27 08:56:25 UTC
Created attachment 1359363 [details]
`time psql foreman --file /tmp/mine.sql > out3.log` only as "SELECT ..."

-bash-4.2$ time psql foreman --file /tmp/mine.sql > out3.log

real	0m0.344s
user	0m0.023s
sys	0m0.010s

Comment 6 sbadhwar 2017-11-27 09:00:31 UTC
(In reply to Chris Duryee from comment #2)
> If you run this sql against the foreman db, does the issue disappear?
> 
> create index test_uuid_idx on katello_subscription_facets(uuid);

Hello Chris,

Thanks for the suggestion, this seems to be working out well for the Query execution time as noted by jhutar. :)

Comment 8 Tomer Brisker 2017-12-11 12:33:47 UTC
Created redmine issue http://projects.theforeman.org/issues/21928 from this bug

Comment 9 pm-sat@redhat.com 2017-12-12 03:06:34 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/21928 has been resolved.

Comment 10 jcallaha 2018-02-06 22:04:35 UTC
Verified in Satellite 6.3 Snap 35.

Added over 25k content hosts to my satellite. Then registered on additional host while monitoring the postgres daily log, with debugging enabled. I also verified that the index was added to katello_subscription_facets. See below for results.

The new query performance time is now less than a second!

foreman=# \d katello_subscription_facets
                                          Table "public.katello_subscription_facets"
       Column       |            Type             |                                 Modifiers                                  
--------------------+-----------------------------+----------------------------------------------------------------------------
...
 uuid               | character varying(255)      | 
...
Indexes:
...
    "index_katello_subscription_facets_on_uuid" btree (uuid)


foreman=# select count(distinct uuid) from katello_subscription_facets;
 count 
-------
 25054


2018-02-06 22:56:48 CET STATEMENT:  SELECT "katello_subscription_facets"."id" FROM "katello_subscription_facets" WHERE "katello_subscription_facets"."uuid" IN ('a187723b-1cef-471a-920b-7a9a9ec970d3', 'a28d1ce0-a1be-4f50-8c3b-
... 
'f0c7cbb8-d164-4d80-91cb-d2dd3806e1c9')

2018-02-06 22:56:48 CET DEBUG:  "katello_subscription_facets": scanned 394 of 394 pages, containing 26055 live rows and 2009 dead rows; 26055 rows in sample, 26055 estimated total rows

Comment 11 pm-sat@redhat.com 2018-02-21 16:54:17 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:0336


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