Re: Increasing work_mem slows down query, why? - Mailing list pgsql-performance

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