Re: Major performance degradation with joins in 15.8 or 15.7? - Mailing list pgsql-performance

On Nov 7, 2024, at 5:18 PM, David Rowley <dgrowleyml@gmail.com> wrote:
> It's impossible to say with the given information. You didn't mention
> which version you upgraded from to start with.

Sorry, 15.6 to 15.7 to 15.8, but we weren't on 15.7 for very long before 15.8.

> You can set random_page_cost for just the session you're connected to
> and try it.  SET random_page_cost = <old value>; before running
> EXPLAIN (ANALYZE, BUFFERS).

Oh, I didn't think of that. Duh. Here it is with random_page_cost = 4.0:

 Nested Loop  (cost=1216.49..11246.62 rows=1 width=112) (actual time=6374.844..6387.845 rows=1 loops=1)
   Join Filter: (CASE WHEN ("position"(a.name, 'zz'::text) = 1) THEN a.name ELSE ('foo_'::text || a.name) END =
"*SELECT*1".table_name) 
   Rows Removed by Join Filter: 1009
   Buffers: shared hit=2227268 read=426 dirtied=1
   ->  Nested Loop  (cost=497.27..5499.27 rows=1 width=54) (actual time=23.852..84.444 rows=1010 loops=1)
         Buffers: shared hit=24458 read=426 dirtied=1
         ->  Nested Loop  (cost=496.85..5495.04 rows=1 width=76) (actual time=23.842..64.212 rows=1010 loops=1)
               Buffers: shared hit=14591 read=426
               ->  Hash Join  (cost=496.43..5490.81 rows=1 width=54) (actual time=23.823..40.587 rows=1010 loops=1)
                     Hash Cond: ((a.name || '.doc'::text) = b_1.name)
                     Buffers: shared hit=4724 read=426
                     ->  Bitmap Heap Scan on metainfo a  (cost=460.62..5400.28 rows=5471 width=38) (actual
time=18.288..32.125rows=1022 loops=1) 
                           Recheck Cond: (relation = 'description'::text)
                           Filter: (type = 'table'::text)
                           Rows Removed by Filter: 37044
                           Heap Blocks: exact=3999
                           Buffers: shared hit=3614 read=425
                           ->  Bitmap Index Scan on metainfo_r  (cost=0.00..459.25 rows=39844 width=0) (actual
time=17.623..17.624rows=44615 loops=1) 
                                 Index Cond: (relation = 'description'::text)
                                 Buffers: shared hit=3 read=37
                     ->  Hash  (cost=35.77..35.77 rows=3 width=38) (actual time=5.511..5.518 rows=1025 loops=1)
                           Buckets: 1024  Batches: 1  Memory Usage: 116kB
                           Buffers: shared hit=1110 read=1
                           ->  Bitmap Heap Scan on metainfo b_1  (cost=23.96..35.77 rows=3 width=38) (actual
time=1.225..4.206rows=1025 loops=1) 
                                 Recheck Cond: ((relation = 'located'::text) AND (type = 'document'::text))
                                 Heap Blocks: exact=1103
                                 Buffers: shared hit=1110 read=1
                                 ->  BitmapAnd  (cost=23.96..23.96 rows=3 width=0) (actual time=0.851..0.856 rows=0
loops=1)
                                       Buffers: shared hit=7 read=1
                                       ->  Bitmap Index Scan on metainfo_r  (cost=0.00..11.86 rows=991 width=0) (actual
time=0.402..0.403rows=1214 loops=1) 
                                             Index Cond: (relation = 'located'::text)
                                             Buffers: shared hit=3 read=1
                                       ->  Bitmap Index Scan on metainfo_t  (cost=0.00..11.86 rows=991 width=0) (actual
time=0.343..0.344rows=1214 loops=1) 
                                             Index Cond: (type = 'document'::text)
                                             Buffers: shared hit=4
               ->  Index Scan using metainfo_n on metainfo c  (cost=0.42..4.22 rows=1 width=22) (actual
time=0.016..0.020rows=1 loops=1010) 
                     Index Cond: (name = a.name)
                     Filter: (relation = 'lastUpdated'::text)
                     Rows Removed by Filter: 48
                     Buffers: shared hit=9867
         ->  Index Scan using metainfo_n on metainfo d  (cost=0.42..4.22 rows=1 width=22) (actual time=0.012..0.017
rows=1loops=1010) 
               Index Cond: (name = a.name)
               Filter: (relation = 'rowcount'::text)
               Rows Removed by Filter: 48
               Buffers: shared hit=9867 dirtied=1
   ->  Append  (cost=719.22..5747.30 rows=2 width=64) (actual time=6.222..6.228 rows=1 loops=1010)
         Buffers: shared hit=2202810
         ->  Subquery Scan on "*SELECT* 1"  (cost=719.22..3653.48 rows=1 width=64) (actual time=5.358..5.358 rows=0
loops=1010)
               Buffers: shared hit=1381680
               ->  Bitmap Heap Scan on metainfo  (cost=719.22..3653.47 rows=1 width=96) (actual time=5.356..5.356
rows=0loops=1010) 
                     Recheck Cond: ((relation = ANY
('{start_time,end_time,dataset_id_column,dataset_id_prefix,original_mission_name,defaultSearchRadius,author,tableType,bibcode,priority,regime,author,include
sTypes,Mission,subject}'::text[])) AND (type = 'table'::text))
                     Filter: ((CASE relation WHEN 'Mission'::text THEN upper(value) ELSE value END = 'foo'::text) AND
(CASErelation WHEN 'defaultSearchRadius'::text THEN 'default_search_radius'::text WHEN 'Mission'::text THEN
'o_name'::textWHEN 'priority'::text THEN 'table_priority'::text WHEN 'bibcode'::text THEN 'catalog_bibcode'::text WHEN
'regime'::textTHEN 'frequency_regime'::text WHEN 'author'::text THEN 'table_author'::text WHEN 'tableType'::text THEN
'table_type'::textWHEN 'subject'::text THEN 'row_type'::text ELSE relation END = 'o_name'::text)) 
                     Rows Removed by Filter: 8253
                     Heap Blocks: exact=1277650
                     Buffers: shared hit=1381680
                     ->  BitmapAnd  (cost=719.18..719.18 rows=1361 width=0) (actual time=2.744..2.744 rows=0
loops=1010)
                           Buffers: shared hit=104030
                           ->  Bitmap Index Scan on metainfo_r  (cost=0.00..140.70 rows=9910 width=0) (actual
time=0.495..0.495rows=9896 loops=1010) 
                                 Index Cond: (relation = ANY
('{start_time,end_time,dataset_id_column,dataset_id_prefix,original_mission_name,defaultSearchRadius,author,tableType,bibcode,priority,regime,author,includesTypes,Mission,subject}'::text[]))
                                 Buffers: shared hit=49490
                           ->  Bitmap Index Scan on metainfo_t  (cost=0.00..578.23 rows=50374 width=0) (actual
time=2.198..2.198rows=58833 loops=1010) 
                                 Index Cond: (type = 'table'::text)
                                 Buffers: shared hit=54540
         ->  Subquery Scan on "*SELECT* 5"  (cost=10.57..2093.81 rows=1 width=64) (actual time=0.862..0.867 rows=1
loops=1010)
               Buffers: shared hit=821130
               ->  Bitmap Heap Scan on metainfo metainfo_1  (cost=10.57..2093.80 rows=1 width=96) (actual
time=0.861..0.864rows=1 loops=1010) 
                     Recheck Cond: (relation = 'containedBy'::text)
                     Filter: ((substr(value, 1, 8) = 'mission:'::text) AND (upper("substring"(value, 9)) =
'foo'::text))
                     Rows Removed by Filter: 721
                     Heap Blocks: exact=818100
                     Buffers: shared hit=821130
                     ->  Bitmap Index Scan on metainfo_r  (cost=0.00..10.56 rows=819 width=0) (actual time=0.076..0.076
rows=895loops=1010) 
                           Index Cond: (relation = 'containedBy'::text)
                           Buffers: shared hit=3030
 Planning:
   Buffers: shared hit=64
 Planning Time: 4.449 ms
 Execution Time: 6388.155 ms
(78 rows)

And here it is with random_page_cost = 2.0:

 Nested Loop  (cost=3695.45..7241.35 rows=1 width=112) (actual time=35.046..49.115 rows=1 loops=1)
   Buffers: shared hit=14243
   ->  Nested Loop  (cost=3695.03..7238.89 rows=1 width=70) (actual time=35.029..49.093 rows=1 loops=1)
         Join Filter: (CASE WHEN ("position"(a.name, 'zz'::text) = 1) THEN a.name ELSE ('foo_'::text || a.name) END =
"*SELECT*1".table_name) 
         Rows Removed by Join Filter: 1009
         Buffers: shared hit=14239
         ->  Nested Loop  (cost=3105.81..3627.24 rows=13 width=38) (actual time=6.688..37.136 rows=1010 loops=1)
               Join Filter: (c.name = a.name)
               Buffers: shared hit=12058
               ->  Merge Join  (cost=3105.39..3116.74 rows=53 width=44) (actual time=6.648..10.798 rows=1010 loops=1)
                     Merge Cond: (c.name = d.name)
                     Buffers: shared hit=2200
                     ->  Sort  (cost=1546.41..1549.10 rows=1076 width=22) (actual time=3.618..4.357 rows=1010 loops=1)
                           Sort Key: c.name
                           Sort Method: quicksort  Memory: 78kB
                           Buffers: shared hit=1101
                           ->  Bitmap Heap Scan on metainfo c  (cost=12.76..1492.22 rows=1076 width=22) (actual
time=0.413..2.446rows=1010 loops=1) 
                                 Recheck Cond: (relation = 'lastUpdated'::text)
                                 Heap Blocks: exact=1097
                                 Buffers: shared hit=1101
                                 ->  Bitmap Index Scan on metainfo_r  (cost=0.00..12.49 rows=1076 width=0) (actual
time=0.250..0.251rows=1200 loops=1) 
                                       Index Cond: (relation = 'lastUpdated'::text)
                                       Buffers: shared hit=4
                     ->  Sort  (cost=1558.98..1561.70 rows=1088 width=22) (actual time=3.022..3.820 rows=1010 loops=1)
                           Sort Key: d.name
                           Sort Method: quicksort  Memory: 78kB
                           Buffers: shared hit=1099
                           ->  Bitmap Heap Scan on metainfo d  (cost=12.85..1504.11 rows=1088 width=22) (actual
time=0.384..1.886rows=1010 loops=1) 
                                 Recheck Cond: (relation = 'rowcount'::text)
                                 Heap Blocks: exact=1095
                                 Buffers: shared hit=1099
                                 ->  Bitmap Index Scan on metainfo_r  (cost=0.00..12.58 rows=1088 width=0) (actual
time=0.236..0.237rows=1200 loops=1) 
                                       Index Cond: (relation = 'rowcount'::text)
                                       Buffers: shared hit=4
               ->  Index Scan using metainfo_n on metainfo a  (cost=0.42..9.62 rows=1 width=38) (actual
time=0.018..0.023rows=1 loops=1010) 
                     Index Cond: (name = d.name)
                     Filter: ((relation = 'description'::text) AND (type = 'table'::text))
                     Rows Removed by Filter: 48
                     Buffers: shared hit=9858
         ->  Materialize  (cost=589.22..3611.08 rows=2 width=64) (actual time=0.009..0.009 rows=1 loops=1010)
               Buffers: shared hit=2181
               ->  Append  (cost=589.22..3611.07 rows=2 width=64) (actual time=7.847..7.870 rows=1 loops=1)
                     Buffers: shared hit=2181
                     ->  Subquery Scan on "*SELECT* 1"  (cost=589.22..2395.08 rows=1 width=64) (actual
time=6.935..6.944rows=0 loops=1) 
                           Buffers: shared hit=1368
                           ->  Bitmap Heap Scan on metainfo  (cost=589.22..2395.07 rows=1 width=96) (actual
time=6.933..6.940rows=0 loops=1) 
                                 Recheck Cond: ((relation = ANY
('{start_time,end_time,dataset_id_column,dataset_id_prefix,original_mission_name,defaultSearchRadius,author,tableType,bibcode,priority,regime,author,includesTypes,Mission,subject}'::text[]))
AND(type = 'table'::text)) 
                                 Filter: ((CASE relation WHEN 'Mission'::text THEN upper(value) ELSE value END =
'foo'::text)AND (CASE relation WHEN 'defaultSearchRadius'::text THEN 'default_search_radius'::text WHEN 'Mission'::text
THEN'o_name'::text WHEN 'priority'::text THEN 'table_priority'::text WHEN 'bibcode'::text THEN 'catalog_bibcode'::text
WHEN'regime'::text THEN 'frequency_regime'::text WHEN 'author'::text THEN 'table_author'::text WHEN 'tableType'::text
THEN'table_type'::text WHEN 'subject'::text THEN 'row_type'::text ELSE relation END = 'o_name'::text)) 
                                 Rows Removed by Filter: 8253
                                 Heap Blocks: exact=1265
                                 Buffers: shared hit=1368
                                 ->  BitmapAnd  (cost=589.18..589.18 rows=1361 width=0) (actual time=3.406..3.412
rows=0loops=1) 
                                       Buffers: shared hit=103
                                       ->  Bitmap Index Scan on metainfo_r  (cost=0.00..110.70 rows=9910 width=0)
(actualtime=0.638..0.638 rows=9897 loops=1) 
                                             Index Cond: (relation = ANY
('{start_time,end_time,dataset_id_column,dataset_id_prefix,original_mission_name,defaultSearchRadius,author,tableType,bibcode,priority,regime,author,includesTypes,Mission,subject}'::text[]))
                                             Buffers: shared hit=49
                                       ->  Bitmap Index Scan on metainfo_t  (cost=0.00..478.23 rows=50374 width=0)
(actualtime=2.688..2.690 rows=58842 loops=1) 
                                             Index Cond: (type = 'table'::text)
                                             Buffers: shared hit=54
                     ->  Subquery Scan on "*SELECT* 5"  (cost=8.57..1215.97 rows=1 width=64) (actual time=0.909..0.919
rows=1loops=1) 
                           Buffers: shared hit=813
                           ->  Bitmap Heap Scan on metainfo metainfo_1  (cost=8.57..1215.96 rows=1 width=96) (actual
time=0.907..0.914rows=1 loops=1) 
                                 Recheck Cond: (relation = 'containedBy'::text)
                                 Filter: ((substr(value, 1, 8) = 'mission:'::text) AND (upper("substring"(value, 9)) =
'foo'::text))
                                 Rows Removed by Filter: 721
                                 Heap Blocks: exact=810
                                 Buffers: shared hit=813
                                 ->  Bitmap Index Scan on metainfo_r  (cost=0.00..8.56 rows=819 width=0) (actual
time=0.085..0.085rows=895 loops=1) 
                                       Index Cond: (relation = 'containedBy'::text)
                                       Buffers: shared hit=3
   ->  Index Scan using metainfo_n on metainfo b_1  (cost=0.42..2.44 rows=1 width=38) (actual time=0.011..0.012 rows=1
loops=1)
         Index Cond: (name = (a.name || '.doc'::text))
         Filter: ((relation = 'located'::text) AND (type = 'document'::text))
         Buffers: shared hit=4
 Planning:
   Buffers: shared hit=367
 Planning Time: 5.391 ms
 Execution Time: 49.412 ms
(78 rows)

Thanks,
Ed