Re: Increasing work_mem slows down query, why?

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...

Thanks!

Regards,
--
Silvio Moioli
SUSE Manager Development Team