Re: Major performance degradation with joins in 15.8 or 15.7?

On Nov 7, 2024, at 5:18 PM, David Rowley <dgrowleyml(at)gmail(dot)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.125 rows=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.624 rows=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.206 rows=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.403 rows=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.344 rows=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.020 rows=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=1 loops=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=0 loops=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 (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=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.495 rows=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.198 rows=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.864 rows=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=895 loops=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.446 rows=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.251 rows=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.886 rows=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.237 rows=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.023 rows=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.944 rows=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.940 rows=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=0 loops=1)
Buffers: shared hit=103
-> Bitmap Index Scan on metainfo_r (cost=0.00..110.70 rows=9910 width=0) (actual time=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) (actual time=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=1 loops=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.914 rows=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.085 rows=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