Thread: Increasing work_mem slows down query, why?
Dear list, here is a pretty contrived case where increasing work_mem produces a worse plan, with much worse overall query time. I wonderwhy that is the case. Problem: INSERTing a thousand new rows in a table which can easily have one million rows. PK is "id", which comes from atable, and we have two columns (called "name" and "version") which do not admit duplicates. Schema here: https://github.com/uyuni-project/uyuni/blob/Uyuni-2020.03/schema/spacewalk/common/tables/rhnPackageCapability.sql Indices here: https://github.com/uyuni-project/uyuni/blob/Uyuni-2020.03/schema/spacewalk/postgres/tables/rhnPackageCapability_index.sql We want one command that returns IDs given (name, version) couples. If they are already in the table, they should be SELECTed,if they are not, they should be INSERTed. Version is NULLable and NULL should be treated as a value. We use: WITH wanted_capability(ordering, name, version) AS ( VALUES (1, 'first_name', '1.0.0'), (2, 'first_name', '1.0.1'), (1, 'second_name', '1.0.0'), ...998 more... ) missing_capability AS ( SELECT wanted_capability.* FROM wanted_capability LEFT JOIN rhnPackageCapability ON wanted_capability.name = rhnPackageCapability.name AND wanted_capability.version IS NOT DISTINCT FROM rhnPackageCapability.version WHERE rhnPackageCapability.id IS NULL ), inserted_capability AS ( INSERT INTO rhnPackageCapability(id, name, version) SELECT nextval('rhn_pkg_capability_id_seq'), name, version FROM missing_capability ON CONFLICT DO NOTHING RETURNING id, name, version ) SELECT wanted_capability.ordering, inserted_capability.id FROM wanted_capability JOIN inserted_capability ON wanted_capability.name = inserted_capability.name AND wanted_capability.version IS NOT DISTINCT FROM inserted_capability.version UNION ( SELECT wanted_capability.ordering, rhnPackageCapability.id FROM wanted_capability JOIN rhnPackageCapability ON wanted_capability.name = rhnPackageCapability.name AND wanted_capability.version IS NOT DISTINCT FROM rhnPackageCapability.version ) ORDER BY ordering ; Behavior at work_mem = 5 MB is pretty good, query finishes in 200ms. Plan: https://explain.dalibo.com/plan/4u Behavior at work_mem = 80 MB seems not equally good, query takes more than 13s. Two expensive SORTs and MERGE JOINs are doneinstead of HASH JOINs. Plan: thttps://explain.dalibo.com/plan/ORd Adding one more INDEX on rhnCapability.name fixes the issue. My question is: why are SORTs chosen if more work_mem is available, and why can't the planner predict query will be slowerthat way? All of the above is reproducible on openSUSE Leap and PostgreSQL 10.12. Ideas welcome, and thanks in advance! Regards, -- Silvio Moioli SUSE Manager Development Team
po 30. 3. 2020 v 8:47 odesílatel Silvio Moioli <moio@suse.de> napsal:
Dear list,
here is a pretty contrived case where increasing work_mem produces a worse plan, with much worse overall query time. I wonder why that is the case.
Problem: INSERTing a thousand new rows in a table which can easily have one million rows. PK is "id", which comes from a table, and we have two columns (called "name" and "version") which do not admit duplicates.
Schema here: https://github.com/uyuni-project/uyuni/blob/Uyuni-2020.03/schema/spacewalk/common/tables/rhnPackageCapability.sql
Indices here: https://github.com/uyuni-project/uyuni/blob/Uyuni-2020.03/schema/spacewalk/postgres/tables/rhnPackageCapability_index.sql
We want one command that returns IDs given (name, version) couples. If they are already in the table, they should be SELECTed, if they are not, they should be INSERTed.
Version is NULLable and NULL should be treated as a value.
We use:
WITH wanted_capability(ordering, name, version) AS (
VALUES (1, 'first_name', '1.0.0'), (2, 'first_name', '1.0.1'), (1, 'second_name', '1.0.0'), ...998 more...
)
missing_capability AS (
SELECT wanted_capability.*
FROM wanted_capability LEFT JOIN rhnPackageCapability
ON wanted_capability.name = rhnPackageCapability.name
AND wanted_capability.version IS NOT DISTINCT FROM rhnPackageCapability.version
WHERE rhnPackageCapability.id IS NULL
),
inserted_capability AS (
INSERT INTO rhnPackageCapability(id, name, version)
SELECT nextval('rhn_pkg_capability_id_seq'), name, version FROM missing_capability ON CONFLICT DO NOTHING
RETURNING id, name, version
)
SELECT wanted_capability.ordering, inserted_capability.id
FROM wanted_capability JOIN inserted_capability
ON wanted_capability.name = inserted_capability.name
AND wanted_capability.version IS NOT DISTINCT FROM inserted_capability.version
UNION (
SELECT wanted_capability.ordering, rhnPackageCapability.id
FROM wanted_capability JOIN rhnPackageCapability
ON wanted_capability.name = rhnPackageCapability.name
AND wanted_capability.version IS NOT DISTINCT FROM rhnPackageCapability.version
)
ORDER BY ordering
;
Behavior at work_mem = 5 MB is pretty good, query finishes in 200ms. Plan: https://explain.dalibo.com/plan/4u
Behavior at work_mem = 80 MB seems not equally good, query takes more than 13s. Two expensive SORTs and MERGE JOINs are done instead of HASH JOINs. Plan: thttps://explain.dalibo.com/plan/ORd
please, can you send explain in text form?
Probably, there is a problem in wrong estimation. What can be expected because CTE is optimization fence in this version
Regards
Pavel
Adding one more INDEX on rhnCapability.name fixes the issue.
My question is: why are SORTs chosen if more work_mem is available, and why can't the planner predict query will be slower that way?
All of the above is reproducible on openSUSE Leap and PostgreSQL 10.12.
Ideas welcome, and thanks in advance!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
On 3/30/20 8:56 AM, Pavel Stehule wrote:
> please, can you send explain in text form?
Sure. With work_mem = 80MB:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=608228.26..608228.27 rows=2 width=36) (actual time=13360.241..13360.454 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=14448
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..552.75 rows=1100 width=68) (actual time=0.001..0.246 rows=1100
loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Merge Left Join (cost=300263.57..303282.17 rows=1 width=68) (actual time=6686.320..6686.320 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Merge Cond: (wanted_capability_2.name = (rhnpackagecapability_1.name)::text)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared hit=7222
-> Sort (cost=1155.57..1158.32 rows=1100 width=68) (actual time=10.011..10.053 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Sort Key: wanted_capability_2.name
Sort Method: quicksort Memory: 203kB
Buffers: shared hit=5
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..1100.00 rows=1100 width=68) (actual
time=0.000..0.516rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
-> Sort (cost=299108.00..300335.41 rows=490964 width=79) (actual time=6475.147..6494.111 rows=462600
loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Sort Key: rhnpackagecapability_1.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964
width=79)(actual time=0.016..59.976 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buffers: shared hit=7217
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..1.51 rows=1 width=1080) (actual
time=6686.322..6686.322rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared hit=7222
-> Subquery Scan on "*SELECT*" (cost=0.00..1.51 rows=1 width=1080) (actual time=6686.321..6686.321 rows=0
loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared hit=7222
-> CTE Scan on missing_capability (cost=0.00..1.00 rows=1 width=72) (actual time=6686.320..6686.320
rows=0loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name,
missing_capability.version
Buffers: shared hit=7222
-> Sort (cost=304391.82..304391.83 rows=2 width=36) (actual time=13360.240..13360.283 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=14448
-> Append (cost=1.50..304391.81 rows=2 width=36) (actual time=13357.167..13360.051 rows=1100 loops=1)
Buffers: shared hit=14442
-> Hash Join (cost=1.50..1108.64 rows=1 width=36) (actual time=6686.340..6686.340 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM
(inserted_capability.version)::text))
Buffers: shared hit=7225
-> CTE Scan on wanted_capability (cost=0.00..1100.00 rows=1100 width=68) (actual
time=0.002..0.002rows=1 loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=1.00..1.00 rows=1 width=1064) (actual time=6686.323..6686.323 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared hit=7222
-> CTE Scan on inserted_capability (cost=0.00..1.00 rows=1 width=1064) (actual
time=6686.322..6686.322rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared hit=7222
-> Merge Join (cost=300263.57..303282.17 rows=1 width=10) (actual time=6670.825..6673.642 rows=1100
loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Merge Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM
(rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Sort (cost=1155.57..1158.32 rows=1100 width=68) (actual time=9.430..9.474 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Sort Key: wanted_capability_1.name
Sort Method: quicksort Memory: 203kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100
width=68)(actual time=0.001..0.066 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name,
wanted_capability_1.version
-> Sort (cost=299108.00..300335.41 rows=490964 width=79) (actual time=6458.988..6477.151
rows=462600loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Sort Key: rhnpackagecapability.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79)
(actualtime=0.012..50.467 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name,
rhnpackagecapability.version
Buffers: shared hit=7217
Planning time: 2.110 ms
Execution time: 13362.965 ms
With work_mem = 5MB:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=648953.89..648953.91 rows=2 width=36) (actual time=221.127..221.337 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=7226 read=7217
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..552.75 rows=1100 width=68) (actual time=0.001..0.266 rows=1100
loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Hash Right Join (cost=1652.75..323644.99 rows=1 width=68) (actual time=137.544..137.544 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Hash Cond: ((rhnpackagecapability_1.name)::text = wanted_capability_2.name)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared read=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964
width=79)(actual time=0.016..77.305 rows=490964 loops=1)
Output: rhnpackagecapability_1.id, rhnpackagecapability_1.name, rhnpackagecapability_1.version,
rhnpackagecapability_1.created,rhnpackagecapability_1.modified
Buffers: shared read=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.812..0.812 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..1100.00 rows=1100 width=68) (actual
time=0.000..0.574rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..1.51 rows=1 width=1080) (actual
time=137.546..137.546rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared read=7217
-> Subquery Scan on "*SELECT*" (cost=0.00..1.51 rows=1 width=1080) (actual time=137.545..137.545 rows=0
loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared read=7217
-> CTE Scan on missing_capability (cost=0.00..1.00 rows=1 width=72) (actual time=137.544..137.545
rows=0loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name,
missing_capability.version
Buffers: shared read=7217
-> Sort (cost=324754.64..324754.65 rows=2 width=36) (actual time=221.126..221.165 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=7226 read=7217
-> Append (cost=1.50..324754.63 rows=2 width=36) (actual time=169.421..220.870 rows=1100 loops=1)
Buffers: shared hit=7220 read=7217
-> Hash Join (cost=1.50..1108.64 rows=1 width=36) (actual time=137.573..137.573 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM
(inserted_capability.version)::text))
Buffers: shared hit=3 read=7217
-> CTE Scan on wanted_capability (cost=0.00..1100.00 rows=1100 width=68) (actual
time=0.002..0.002rows=1 loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=1.00..1.00 rows=1 width=1064) (actual time=137.547..137.547 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared read=7217
-> CTE Scan on inserted_capability (cost=0.00..1.00 rows=1 width=1064) (actual
time=137.547..137.547rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared read=7217
-> Hash Join (cost=1652.75..323644.99 rows=1 width=10) (actual time=31.846..83.234 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: ((rhnpackagecapability.name)::text = wanted_capability_1.name)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM
(rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual
time=0.007..29.702rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version,
rhnpackagecapability.created,rhnpackagecapability.modified
Buffers: shared hit=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.257..0.257 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100
width=68)(actual time=0.001..0.067 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name,
wanted_capability_1.version
Planning time: 3.232 ms
Execution time: 221.668 ms
> Probably, there is a problem in wrong estimation.
Yes, that's what I would also assume.
> What can be expected because CTE is optimization fence in this version
I am aware of that, but would not expect it to really be a problem in this specific case. Fact that CTE is an
optimizationfence is true regardless of work_mem, so ATM I cannot see why it would lead to slow down the query in high
work_memcase.
I am sure I am still missing something...
Thanks!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
po 30. 3. 2020 v 10:12 odesílatel Silvio Moioli <moio@suse.de> napsal:
On 3/30/20 8:56 AM, Pavel Stehule wrote:
> please, can you send explain in text form?
Sure. With work_mem = 80MB:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=608228.26..608228.27 rows=2 width=36) (actual time=13360.241..13360.454 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=14448
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..552.75 rows=1100 width=68) (actual time=0.001..0.246 rows=1100 loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Merge Left Join (cost=300263.57..303282.17 rows=1 width=68) (actual time=6686.320..6686.320 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Merge Cond: (wanted_capability_2.name = (rhnpackagecapability_1.name)::text)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared hit=7222
-> Sort (cost=1155.57..1158.32 rows=1100 width=68) (actual time=10.011..10.053 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Sort Key: wanted_capability_2.name
Sort Method: quicksort Memory: 203kB
Buffers: shared hit=5
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.000..0.516 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
-> Sort (cost=299108.00..300335.41 rows=490964 width=79) (actual time=6475.147..6494.111 rows=462600 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Sort Key: rhnpackagecapability_1.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.016..59.976 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buffers: shared hit=7217
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..1.51 rows=1 width=1080) (actual time=6686.322..6686.322 rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared hit=7222
-> Subquery Scan on "*SELECT*" (cost=0.00..1.51 rows=1 width=1080) (actual time=6686.321..6686.321 rows=0 loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared hit=7222
-> CTE Scan on missing_capability (cost=0.00..1.00 rows=1 width=72) (actual time=6686.320..6686.320 rows=0 loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name, missing_capability.version
Buffers: shared hit=7222
-> Sort (cost=304391.82..304391.83 rows=2 width=36) (actual time=13360.240..13360.283 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=14448
-> Append (cost=1.50..304391.81 rows=2 width=36) (actual time=13357.167..13360.051 rows=1100 loops=1)
Buffers: shared hit=14442
-> Hash Join (cost=1.50..1108.64 rows=1 width=36) (actual time=6686.340..6686.340 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM (inserted_capability.version)::text))
Buffers: shared hit=7225
-> CTE Scan on wanted_capability (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.002..0.002 rows=1 loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=1.00..1.00 rows=1 width=1064) (actual time=6686.323..6686.323 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared hit=7222
-> CTE Scan on inserted_capability (cost=0.00..1.00 rows=1 width=1064) (actual time=6686.322..6686.322 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared hit=7222
-> Merge Join (cost=300263.57..303282.17 rows=1 width=10) (actual time=6670.825..6673.642 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Merge Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Sort (cost=1155.57..1158.32 rows=1100 width=68) (actual time=9.430..9.474 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Sort Key: wanted_capability_1.name
Sort Method: quicksort Memory: 203kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.001..0.066 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Sort (cost=299108.00..300335.41 rows=490964 width=79) (actual time=6458.988..6477.151 rows=462600 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Sort Key: rhnpackagecapability.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.012..50.467 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
Planning time: 2.110 ms
Execution time: 13362.965 ms
With work_mem = 5MB:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=648953.89..648953.91 rows=2 width=36) (actual time=221.127..221.337 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=7226 read=7217
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..552.75 rows=1100 width=68) (actual time=0.001..0.266 rows=1100 loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Hash Right Join (cost=1652.75..323644.99 rows=1 width=68) (actual time=137.544..137.544 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Hash Cond: ((rhnpackagecapability_1.name)::text = wanted_capability_2.name)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared read=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.016..77.305 rows=490964 loops=1)
Output: rhnpackagecapability_1.id, rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.created, rhnpackagecapability_1.modified
Buffers: shared read=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.812..0.812 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.000..0.574 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..1.51 rows=1 width=1080) (actual time=137.546..137.546 rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared read=7217
-> Subquery Scan on "*SELECT*" (cost=0.00..1.51 rows=1 width=1080) (actual time=137.545..137.545 rows=0 loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared read=7217
-> CTE Scan on missing_capability (cost=0.00..1.00 rows=1 width=72) (actual time=137.544..137.545 rows=0 loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name, missing_capability.version
Buffers: shared read=7217
-> Sort (cost=324754.64..324754.65 rows=2 width=36) (actual time=221.126..221.165 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=7226 read=7217
-> Append (cost=1.50..324754.63 rows=2 width=36) (actual time=169.421..220.870 rows=1100 loops=1)
Buffers: shared hit=7220 read=7217
-> Hash Join (cost=1.50..1108.64 rows=1 width=36) (actual time=137.573..137.573 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM (inserted_capability.version)::text))
Buffers: shared hit=3 read=7217
-> CTE Scan on wanted_capability (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.002..0.002 rows=1 loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=1.00..1.00 rows=1 width=1064) (actual time=137.547..137.547 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared read=7217
-> CTE Scan on inserted_capability (cost=0.00..1.00 rows=1 width=1064) (actual time=137.547..137.547 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared read=7217
-> Hash Join (cost=1652.75..323644.99 rows=1 width=10) (actual time=31.846..83.234 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: ((rhnpackagecapability.name)::text = wanted_capability_1.name)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.007..29.702 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version, rhnpackagecapability.created, rhnpackagecapability.modified
Buffers: shared hit=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.257..0.257 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.001..0.067 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Planning time: 3.232 ms
Execution time: 221.668 ms
> Probably, there is a problem in wrong estimation.
Yes, that's what I would also assume.
> What can be expected because CTE is optimization fence in this version
I am aware of that, but would not expect it to really be a problem in this specific case. Fact that CTE is an optimization fence is true regardless of work_mem, so ATM I cannot see why it would lead to slow down the query in high work_mem case.
I am sure I am still missing something...
This parts looks strange
-> Sort (cost=299108.00..300335.41 rows=490964 width=79) (actual time=6458.988..6477.151 rows=462600 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Sort Key: rhnpackagecapability.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.012..50.467 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Sort Key: rhnpackagecapability.name
Sort Method: quicksort Memory: 79862kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.012..50.467 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
postgres=# explain (analyze, buffers) select * from foo2 join foo3 on foo2.name = foo3.name;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Hash Join (cost=188.62..33869.93 rows=866330 width=78) (actual time=6.247..369.081 rows=934000 loops=1)
Hash Cond: (foo2.name = foo3.name)
Buffers: shared hit=2224 read=4092
-> Seq Scan on foo2 (cost=0.00..12518.00 rows=625000 width=48) (actual time=0.095..70.174 rows=625000 loops=1)
Buffers: shared hit=2176 read=4092
-> Hash (cost=110.50..110.50 rows=6250 width=30) (actual time=6.116..6.116 rows=6250 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 447kB
Buffers: shared hit=48
-> Seq Scan on foo3 (cost=0.00..110.50 rows=6250 width=30) (actual time=0.014..1.801 rows=6250 loops=1)
Buffers: shared hit=48
Planning Time: 1.190 ms
Execution Time: 414.264 ms
(12 rows)
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Hash Join (cost=188.62..33869.93 rows=866330 width=78) (actual time=6.247..369.081 rows=934000 loops=1)
Hash Cond: (foo2.name = foo3.name)
Buffers: shared hit=2224 read=4092
-> Seq Scan on foo2 (cost=0.00..12518.00 rows=625000 width=48) (actual time=0.095..70.174 rows=625000 loops=1)
Buffers: shared hit=2176 read=4092
-> Hash (cost=110.50..110.50 rows=6250 width=30) (actual time=6.116..6.116 rows=6250 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 447kB
Buffers: shared hit=48
-> Seq Scan on foo3 (cost=0.00..110.50 rows=6250 width=30) (actual time=0.014..1.801 rows=6250 loops=1)
Buffers: shared hit=48
Planning Time: 1.190 ms
Execution Time: 414.264 ms
(12 rows)
postgres=# explain (analyze, buffers) select * from foo2 join foo3 on foo2.name = foo3.name;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Merge Join (cost=73189.73..86215.92 rows=866330 width=78) (actual time=1499.805..1835.262 rows=934000 loops=1)
Merge Cond: (foo3.name = foo2.name)
Buffers: shared hit=2261 read=4060, temp read=13104 written=10023
-> Sort (cost=504.55..520.18 rows=6250 width=30) (actual time=21.313..21.895 rows=6250 loops=1)
Sort Key: foo3.name
Sort Method: quicksort Memory: 763kB
Buffers: shared hit=53
-> Seq Scan on foo3 (cost=0.00..110.50 rows=6250 width=30) (actual time=0.017..1.802 rows=6250 loops=1)
Buffers: shared hit=48
-> Sort (cost=72685.18..74247.68 rows=625000 width=48) (actual time=1478.480..1602.358 rows=933999 loops=1)
Sort Key: foo2.name
Sort Method: external sort Disk: 40088kB
Buffers: shared hit=2208 read=4060, temp read=12196 written=10023
-> Seq Scan on foo2 (cost=0.00..12518.00 rows=625000 width=48) (actual time=0.039..63.340 rows=625000 loops=1)
Buffers: shared hit=2208 read=4060
Planning Time: 1.116 ms
Execution Time: 1884.985 ms
(17 rows)
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Merge Join (cost=73189.73..86215.92 rows=866330 width=78) (actual time=1499.805..1835.262 rows=934000 loops=1)
Merge Cond: (foo3.name = foo2.name)
Buffers: shared hit=2261 read=4060, temp read=13104 written=10023
-> Sort (cost=504.55..520.18 rows=6250 width=30) (actual time=21.313..21.895 rows=6250 loops=1)
Sort Key: foo3.name
Sort Method: quicksort Memory: 763kB
Buffers: shared hit=53
-> Seq Scan on foo3 (cost=0.00..110.50 rows=6250 width=30) (actual time=0.017..1.802 rows=6250 loops=1)
Buffers: shared hit=48
-> Sort (cost=72685.18..74247.68 rows=625000 width=48) (actual time=1478.480..1602.358 rows=933999 loops=1)
Sort Key: foo2.name
Sort Method: external sort Disk: 40088kB
Buffers: shared hit=2208 read=4060, temp read=12196 written=10023
-> Seq Scan on foo2 (cost=0.00..12518.00 rows=625000 width=48) (actual time=0.039..63.340 rows=625000 loops=1)
Buffers: shared hit=2208 read=4060
Planning Time: 1.116 ms
Execution Time: 1884.985 ms
(17 rows)
And looks little bit strange the cost on seq scan on foo2 12K against cost of your public.rhnpackagecapability - 252K.
Do you have some planner variables changed - like seq_page_cost?
I did some tests and it looks so a penalization for sort long keys is not too high. In your case it is reason why sort is very slow (probably due slow locales). Then the cost of hash join and sort is similar, although in reality it is not true.
On your plan is strange the cost of seq scan. It is surprisingly high.
Regards
Pavel
Thanks!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
On 3/30/20 12:12 PM, Pavel Stehule wrote:
> Do you have some planner variables changed - like seq_page_cost?
That one was not changed but another one is - cpu_tuple_cost (to 0.5). Indeed bringing it back to its default does
improvethe query time significantly:
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=36735.61..36735.63 rows=2 width=36) (actual time=357.825..358.036 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=14443
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..13.75 rows=1100 width=68) (actual time=0.001..0.355 rows=1100 loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Hash Left Join (cost=18263.69..18347.78 rows=1 width=68) (actual time=183.826..183.826 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Hash Cond: (wanted_capability_2.name = (rhnpackagecapability_1.name)::text)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..22.00 rows=1100 width=68) (actual
time=0.000..0.729rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=181.477..181.477 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buckets: 524288 Batches: 1 Memory Usage: 53907kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..12126.64 rows=490964
width=79)(actual time=0.009..57.663 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buffers: shared hit=7217
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..0.04 rows=1 width=1080) (actual
time=183.828..183.828rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared hit=7217
-> Subquery Scan on "*SELECT*" (cost=0.00..0.04 rows=1 width=1080) (actual time=183.827..183.827 rows=0
loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared hit=7217
-> CTE Scan on missing_capability (cost=0.00..0.02 rows=1 width=72) (actual time=183.827..183.827
rows=0loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name,
missing_capability.version
Buffers: shared hit=7217
-> Sort (cost=18374.04..18374.04 rows=2 width=36) (actual time=357.825..357.862 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=14443
-> Append (cost=0.03..18374.03 rows=2 width=36) (actual time=357.071..357.660 rows=1100 loops=1)
Buffers: shared hit=14437
-> Hash Join (cost=0.03..26.23 rows=1 width=36) (actual time=183.847..183.847 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM
(inserted_capability.version)::text))
Buffers: shared hit=7220
-> CTE Scan on wanted_capability (cost=0.00..22.00 rows=1100 width=68) (actual time=0.002..0.002
rows=1loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=0.02..0.02 rows=1 width=1064) (actual time=183.829..183.829 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared hit=7217
-> CTE Scan on inserted_capability (cost=0.00..0.02 rows=1 width=1064) (actual
time=183.828..183.828rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared hit=7217
-> Hash Join (cost=18263.69..18347.78 rows=1 width=10) (actual time=173.223..173.750 rows=1100
loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM
(rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68)
(actualtime=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964
loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79)
(actualtime=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name,
rhnpackagecapability.version
Buffers: shared hit=7217
Planning time: 2.145 ms
Execution time: 358.773 ms
Is that an unreasonable value? For the sake of this discussison, I am targeting fairly average bare-metal SSD-backed
serverswith recent CPUs (let's say 3 year old maximum), with ample available RAM.
Thanks!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
po 30. 3. 2020 v 15:09 odesílatel Silvio Moioli <moio@suse.de> napsal:
On 3/30/20 12:12 PM, Pavel Stehule wrote:
> Do you have some planner variables changed - like seq_page_cost?
That one was not changed but another one is - cpu_tuple_cost (to 0.5). Indeed bringing it back to its default does improve the query time significantly:
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=36735.61..36735.63 rows=2 width=36) (actual time=357.825..358.036 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Buffers: shared hit=14443
CTE wanted_capability
-> Values Scan on "*VALUES*" (cost=0.00..13.75 rows=1100 width=68) (actual time=0.001..0.355 rows=1100 loops=1)
Output: "*VALUES*".column1, "*VALUES*".column2, "*VALUES*".column3
CTE missing_capability
-> Hash Left Join (cost=18263.69..18347.78 rows=1 width=68) (actual time=183.826..183.826 rows=0 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
Hash Cond: (wanted_capability_2.name = (rhnpackagecapability_1.name)::text)
Join Filter: (NOT (wanted_capability_2.version IS DISTINCT FROM (rhnpackagecapability_1.version)::text))
Filter: (rhnpackagecapability_1.id IS NULL)
Rows Removed by Filter: 1100
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_2 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.729 rows=1100 loops=1)
Output: wanted_capability_2.ordering, wanted_capability_2.name, wanted_capability_2.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=181.477..181.477 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buckets: 524288 Batches: 1 Memory Usage: 53907kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.009..57.663 rows=490964 loops=1)
Output: rhnpackagecapability_1.name, rhnpackagecapability_1.version, rhnpackagecapability_1.id
Buffers: shared hit=7217
CTE inserted_capability
-> Insert on public.rhnpackagecapability rhnpackagecapability_2 (cost=0.00..0.04 rows=1 width=1080) (actual time=183.828..183.828 rows=0 loops=1)
Output: rhnpackagecapability_2.id, rhnpackagecapability_2.name, rhnpackagecapability_2.version
Conflict Resolution: NOTHING
Tuples Inserted: 0
Conflicting Tuples: 0
Buffers: shared hit=7217
-> Subquery Scan on "*SELECT*" (cost=0.00..0.04 rows=1 width=1080) (actual time=183.827..183.827 rows=0 loops=1)
Output: "*SELECT*".nextval, "*SELECT*".name, "*SELECT*".version, CURRENT_TIMESTAMP, CURRENT_TIMESTAMP
Buffers: shared hit=7217
-> CTE Scan on missing_capability (cost=0.00..0.02 rows=1 width=72) (actual time=183.827..183.827 rows=0 loops=1)
Output: nextval('rhn_pkg_capability_id_seq'::regclass), missing_capability.name, missing_capability.version
Buffers: shared hit=7217
-> Sort (cost=18374.04..18374.04 rows=2 width=36) (actual time=357.825..357.862 rows=1100 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Sort Key: wanted_capability.ordering, inserted_capability.id
Sort Method: quicksort Memory: 100kB
Buffers: shared hit=14443
-> Append (cost=0.03..18374.03 rows=2 width=36) (actual time=357.071..357.660 rows=1100 loops=1)
Buffers: shared hit=14437
-> Hash Join (cost=0.03..26.23 rows=1 width=36) (actual time=183.847..183.847 rows=0 loops=1)
Output: wanted_capability.ordering, inserted_capability.id
Hash Cond: (wanted_capability.name = (inserted_capability.name)::text)
Join Filter: (NOT (wanted_capability.version IS DISTINCT FROM (inserted_capability.version)::text))
Buffers: shared hit=7220
-> CTE Scan on wanted_capability (cost=0.00..22.00 rows=1100 width=68) (actual time=0.002..0.002 rows=1 loops=1)
Output: wanted_capability.ordering, wanted_capability.name, wanted_capability.version
-> Hash (cost=0.02..0.02 rows=1 width=1064) (actual time=183.829..183.829 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buckets: 1024 Batches: 1 Memory Usage: 8kB
Buffers: shared hit=7217
-> CTE Scan on inserted_capability (cost=0.00..0.02 rows=1 width=1064) (actual time=183.828..183.828 rows=0 loops=1)
Output: inserted_capability.id, inserted_capability.name, inserted_capability.version
Buffers: shared hit=7217
-> Hash Join (cost=18263.69..18347.78 rows=1 width=10) (actual time=173.223..173.750 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
Planning time: 2.145 ms
Execution time: 358.773 ms
Is that an unreasonable value? For the sake of this discussison, I am targeting fairly average bare-metal SSD-backed servers with recent CPUs (let's say 3 year old maximum), with ample available RAM.
these numbers are artificial - important is stable behave, and it's hard to say, what is correct value. But when these values are out of good range, then some calculations can be unstable and generated plans can be strange.
There is interesting another fact, new plan uses hash from bigger table, and then hash join is slower. This is strange.
-> Hash Join (cost=18263.69..18347.78 rows=1 width=10) (actual time=173.223..173.750 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
versus
-> Hash Join (cost=1652.75..323644.99 rows=1 width=10) (actual time=31.846..83.234 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: ((rhnpackagecapability.name)::text = wanted_capability_1.name)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.007..29.702 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version, rhnpackagecapability.created, rhnpackagecapability.modified
Buffers: shared hit=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.257..0.257 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.001..0.067 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: ((rhnpackagecapability.name)::text = wanted_capability_1.name)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.007..29.702 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version, rhnpackagecapability.created, rhnpackagecapability.modified
Buffers: shared hit=7217
-> Hash (cost=1100.00..1100.00 rows=1100 width=68) (actual time=0.257..0.257 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Buckets: 2048 Batches: 1 Memory Usage: 134kB
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..1100.00 rows=1100 width=68) (actual time=0.001..0.067 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
Thanks!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
Is that an unreasonable value? For the sake of this discussison, I am targeting fairly average bare-metal SSD-backed servers with recent CPUs (let's say 3 year old maximum), with ample available RAM.
if you have SSD, then you can decrease RANDOM_PAGE_COST to 2 maybe 1.5. But probably there will not be impact to this query.
Thanks!
Regards,
--
Silvio Moioli
SUSE Manager Development Team
Pavel Stehule <pavel.stehule@gmail.com> writes:
> po 30. 3. 2020 v 10:12 odesílatel Silvio Moioli <moio@suse.de> napsal:
>> -> Sort (cost=299108.00..300335.41 rows=490964 width=79)
>> (actual time=6475.147..6494.111 rows=462600 loops=1)
>> Output: rhnpackagecapability_1.name,
>> rhnpackagecapability_1.version, rhnpackagecapability_1.id
>> Sort Key: rhnpackagecapability_1.name
>> Sort Method: quicksort Memory: 79862kB
>> Buffers: shared hit=7217
>> -> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964
width=79)(actual time=0.016..59.976 rows=490964 loops=1)
>> -> Sort (cost=299108.00..300335.41 rows=490964
>> width=79) (actual time=6458.988..6477.151 rows=462600 loops=1)
>> Output: rhnpackagecapability.id,
>> rhnpackagecapability.name, rhnpackagecapability.version
>> Sort Key: rhnpackagecapability.name
>> Sort Method: quicksort Memory: 79862kB
>> Buffers: shared hit=7217
>> -> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual
time=0.012..50.467rows=490964 loops=1)
> I did some tests and it looks so a penalization for sort long keys is not
> too high. In your case it is reason why sort is very slow (probably due
> slow locales). Then the cost of hash join and sort is similar, although in
> reality it is not true.
Yeah, the run time of the slow query seems to be almost entirely expended
in these two sort steps, while the planner doesn't think that they'll be
very expensive. Tweaking unrelated cost settings to work around that is
not going to be helpful. What you'd be better off trying to do is fix
the slow sorting. Is rhnpackagecapability.name some peculiar datatype?
If it's just relatively short text strings, as one would guess from the
column name, then what you must be looking at is really slow locale-based
sorting. What's the database's LC_COLLATE setting? Can you get away
with switching it to C?
regards, tom lane
po 30. 3. 2020 v 18:02 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:
Pavel Stehule <pavel.stehule@gmail.com> writes:
> po 30. 3. 2020 v 10:12 odesílatel Silvio Moioli <moio@suse.de> napsal:
>> -> Sort (cost=299108.00..300335.41 rows=490964 width=79)
>> (actual time=6475.147..6494.111 rows=462600 loops=1)
>> Output: rhnpackagecapability_1.name,
>> rhnpackagecapability_1.version, rhnpackagecapability_1.id
>> Sort Key: rhnpackagecapability_1.name
>> Sort Method: quicksort Memory: 79862kB
>> Buffers: shared hit=7217
>> -> Seq Scan on public.rhnpackagecapability rhnpackagecapability_1 (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.016..59.976 rows=490964 loops=1)
>> -> Sort (cost=299108.00..300335.41 rows=490964
>> width=79) (actual time=6458.988..6477.151 rows=462600 loops=1)
>> Output: rhnpackagecapability.id,
>> rhnpackagecapability.name, rhnpackagecapability.version
>> Sort Key: rhnpackagecapability.name
>> Sort Method: quicksort Memory: 79862kB
>> Buffers: shared hit=7217
>> -> Seq Scan on public.rhnpackagecapability (cost=0.00..252699.00 rows=490964 width=79) (actual time=0.012..50.467 rows=490964 loops=1)
> I did some tests and it looks so a penalization for sort long keys is not
> too high. In your case it is reason why sort is very slow (probably due
> slow locales). Then the cost of hash join and sort is similar, although in
> reality it is not true.
Yeah, the run time of the slow query seems to be almost entirely expended
in these two sort steps, while the planner doesn't think that they'll be
very expensive. Tweaking unrelated cost settings to work around that is
not going to be helpful. What you'd be better off trying to do is fix
the slow sorting. Is rhnpackagecapability.name some peculiar datatype?
If it's just relatively short text strings, as one would guess from the
column name, then what you must be looking at is really slow locale-based
sorting. What's the database's LC_COLLATE setting? Can you get away
with switching it to C?
There is another interesting thing
-> Hash Join (cost=18263.69..18347.78 rows=1 width=10) (actual time=173.223..173.750 rows=1100 loops=1)
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
Output: wanted_capability_1.ordering, rhnpackagecapability.id
Hash Cond: (wanted_capability_1.name = (rhnpackagecapability.name)::text)
Join Filter: (NOT (wanted_capability_1.version IS DISTINCT FROM (rhnpackagecapability.version)::text))
Buffers: shared hit=7217
-> CTE Scan on wanted_capability wanted_capability_1 (cost=0.00..22.00 rows=1100 width=68) (actual time=0.000..0.070 rows=1100 loops=1)
Output: wanted_capability_1.ordering, wanted_capability_1.name, wanted_capability_1.version
-> Hash (cost=12126.64..12126.64 rows=490964 width=79) (actual time=172.220..172.220 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buckets: 524288 Batches: 1 Memory Usage: 53922kB
Buffers: shared hit=7217
-> Seq Scan on public.rhnpackagecapability (cost=0.00..12126.64 rows=490964 width=79) (actual time=0.008..52.573 rows=490964 loops=1)
Output: rhnpackagecapability.id, rhnpackagecapability.name, rhnpackagecapability.version
Buffers: shared hit=7217
CTE scan has only 1100 rows, public.rhnpackagecapability has 490964 rows. But planner does hash from public.rhnpackagecapability table. It cannot be very effective.
Pavel
regards, tom lane
Pavel Stehule <pavel.stehule@gmail.com> writes:
> CTE scan has only 1100 rows, public.rhnpackagecapability has 490964 rows.
> But planner does hash from public.rhnpackagecapability table. It cannot be
> very effective.
[ shrug... ] Without stats on the CTE output, the planner is very
leery of putting it on the inside of a hash join. The CTE might
produce output that ends up in just a few hash buckets, degrading
the join to something not much better than a nested loop. As long
as there's enough memory to hash the known-well-distributed table,
putting it on the inside is safer and no costlier.
regards, tom lane
po 30. 3. 2020 v 18:36 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:
Pavel Stehule <pavel.stehule@gmail.com> writes:
> CTE scan has only 1100 rows, public.rhnpackagecapability has 490964 rows.
> But planner does hash from public.rhnpackagecapability table. It cannot be
> very effective.
[ shrug... ] Without stats on the CTE output, the planner is very
leery of putting it on the inside of a hash join. The CTE might
produce output that ends up in just a few hash buckets, degrading
the join to something not much better than a nested loop. As long
as there's enough memory to hash the known-well-distributed table,
putting it on the inside is safer and no costlier.
ok
Regards
Pavel
regards, tom lane
On 3/30/20 6:02 PM, Tom Lane wrote: > Yeah, the run time of the slow query seems to be almost entirely expended > in these two sort steps, while the planner doesn't think that they'll be > very expensive. Tweaking unrelated cost settings to work around that is > not going to be helpful. What you'd be better off trying to do is fix > the slow sorting. Is rhnpackagecapability.name some peculiar datatype? > If it's just relatively short text strings, as one would guess from the > column name, then what you must be looking at is really slow locale-based > sorting. What's the database's LC_COLLATE setting? Can you get away > with switching it to C? LC_COLLATE is en_US.UTF-8, and I cannot really change that for the whole database. I could, in principle, use the "C" collationfor this particular column, I tried that and it helps (time goes down from ~13s to ~500ms). Nevertheless, adding an explicit new index on the column (CREATE INDEX rhn_pkg_cap_name ON rhnPackageCapability (name)) helpseven more, with the query time going down to ~60ms, no matter work_mem. So ultimately I think I am going to remove the custom cpu_tuple_cost parameter and add the index, unless you have differentsuggestions. Thank you very much so far! Regards, -- Silvio Moioli SUSE Manager Development Team