Re: Increasing work_mem slows down query, why?

[Pavel Stehule <pavel.stehule@xxxxxxxxx>]

po 30. 3. 2020 v 15:09 odesílatel Silvio Moioli <moio@xxxxxxx> 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

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

Thanks!

Regards,
--
Silvio Moioli
SUSE Manager Development Team