public inbox for pgsql-bugs@postgresql.org
help / color / mirror / Atom feedFrom: Tomas Vondra <tomas@vondra.me>
To: Adrian Mönnich <adrian.moennich@cern.ch>
To: Andres Freund <andres@anarazel.de>
Cc: pgsql-bugs@lists.postgresql.org
Cc: Tomas Vondra <tv@fuzzy.cz>
Cc: Thomas Munro <thomas.munro@gmail.com>
Subject: Re: BUG #19449: Massive performance degradation for complex query on Postgres 16+ (few seconds -> multiple hours)
Date: Thu, 2 Apr 2026 20:12:38 +0200
Message-ID: <2747373b-d188-43b1-8e49-66f9e23e3c24@vondra.me> (raw)
In-Reply-To: <94712944.20260402164957@cern.ch>
References: <19449-4fac687c06cc7def@postgresql.org>
<dihw6lynx3p75sv5fbgqjlsu3kfeagcnm4px2r7mgsvf4w2sf5@53udqm4e5wid>
<43225458.20260402160627@cern.ch>
<jivwllcuyvd7m4ceydwwpjptmadfe3cfbw47hqnej7yjfkleej@2q33rbrfybm4>
<94712944.20260402164957@cern.ch>
Hi,
I can reproduce the performance getting much worse in 16, using the
provided SQL scripts. This is what I see:
14: 1551.363 ms
15: 1385.414 ms
16: 161571.400 ms
17: 156434.543 ms
18: 159095.001 ms
I'm attaching the explains for 15+16. I don't know what's causing it,
but I have a couple interesting observations.
1) If I disable parallel query, the timings change to
14: 3990.439 ms
15: 3518.453 ms
16: 3606.460 ms
17: 3591.039 ms
18: 3617.872 ms
So no regression in this case. It seems to be related to parallelism.
2) There seems to be an explosion of temporary files. We don't have that
in explain, but I queried pg_stat_database before/after the query, and
there's huge difference. Both start at
temp_files | 112
temp_bytes | 1942275280
so 112 files, ~2GB disk space. But after the query, 15 says
temp_files | 721
temp_bytes | 2755839184
while 16 has
temp_files | 2078995
temp_bytes | 70607906000
2M files and 70GB? Wow!
3) Indeed, before the query completes the pgsql_tmp directory has this:
63M pgsql_tmp3499395.0.fileset
63G pgsql_tmp3499395.1.fileset
95M pgsql_tmp3499395.2.fileset
95M pgsql_tmp3499395.3.fileset
127M pgsql_tmp3499395.4.fileset
So I guess that's one of the parallel hash joins doing something, and
consuming 63GB of disk space? I don't see anything suspicious in the
plan, but I assume parallel HJ may not report the relevant stats.
FWIW bumping up work_mem (to 64MB) solved this with the sample data.
I suspect this is going to be something like the hash join explosion,
where we just happen to add more and more batches. I don't have time to
investigate this more at the moment.
regards
--
Tomas Vondra
Attachments:
[text/x-log] 16.log (6.7K, 2-16.log)
download | inline:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=424803.70..424803.71 rows=1 width=8) (actual time=143020.230..161567.872 rows=1 loops=1)
-> Gather (cost=424803.48..424803.69 rows=2 width=8) (actual time=142964.457..161567.851 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Partial Aggregate (cost=423803.48..423803.49 rows=1 width=8) (actual time=142963.280..142968.559 rows=1 loops=3)
-> Parallel Hash Join (cost=338640.72..421783.68 rows=807919 width=4) (actual time=142746.820..142933.580 rows=1523232 loops=3)
Hash Cond: (attachments.folder_id = folders.id)
-> Parallel Seq Scan on attachments (cost=0.00..54748.97 rows=1980177 width=8) (actual time=0.233..85.380 rows=1576685 loops=3)
Filter: (NOT is_deleted)
Rows Removed by Filter: 327767
-> Parallel Hash (cost=329694.99..329694.99 rows=545258 width=4) (actual time=142532.861..142538.136 rows=1030633 loops=3)
Buckets: 262144 Batches: 16 Memory Usage: 9664kB
-> Parallel Hash Right Join (cost=228094.50..329694.99 rows=545258 width=4) (actual time=48620.655..142449.984 rows=1030633 loops=3)
Hash Cond: (contributions.id = folders.contribution_id)
Filter: (NOT COALESCE(sessions.is_deleted, contributions.is_deleted, subcontributions.is_deleted, false))
Rows Removed by Filter: 5283
-> Parallel Seq Scan on contributions (cost=0.00..61461.31 rows=2674131 width=5) (actual time=0.034..149.134 rows=2139359 loops=3)
-> Parallel Hash (cost=209138.05..209138.05 rows=1090516 width=10) (actual time=22774.998..22775.308 rows=1035916 loops=3)
Buckets: 262144 (originally 262144) Batches: 262144 (originally 32) Memory Usage: 19168kB
-> Parallel Hash Left Join (cost=115722.60..209138.05 rows=1090516 width=10) (actual time=542.858..617.491 rows=1035916 loops=3)
Hash Cond: (folders.session_id = sessions.id)
-> Parallel Hash Left Join (cost=105930.64..184862.48 rows=1090516 width=13) (actual time=412.124..472.199 rows=1035916 loops=3)
Hash Cond: (folders.subcontribution_id = subcontributions.id)
Filter: ((contributions_1.is_deleted IS NULL) OR (NOT contributions_1.is_deleted))
Rows Removed by Filter: 150
-> Parallel Hash Join (cost=23682.51..85276.38 rows=1163755 width=16) (actual time=158.760..242.455 rows=1036066 loops=3)
Hash Cond: (folders.event_id = events.id)
-> Parallel Seq Scan on folders (cost=0.00..40321.07 rows=1331730 width=20) (actual time=0.009..58.211 rows=1064701 loops=3)
Filter: ((NOT is_deleted) AND (link_type <> 1))
Rows Removed by Filter: 4424
-> Parallel Hash (cost=14575.53..14575.53 rows=555039 width=4) (actual time=40.413..40.418 rows=444370 loops=3)
Buckets: 262144 Batches: 16 Memory Usage: 5344kB
-> Parallel Seq Scan on events (cost=0.00..14575.53 rows=555039 width=4) (actual time=0.009..19.095 rows=444370 loops=3)
Filter: (NOT is_deleted)
Rows Removed by Filter: 63752
-> Parallel Hash (cost=76907.44..76907.44 rows=325495 width=6) (actual time=119.187..119.190 rows=184447 loops=3)
Buckets: 262144 Batches: 4 Memory Usage: 8576kB
-> Nested Loop Left Join (cost=0.44..76907.44 rows=325495 width=6) (actual time=0.026..105.242 rows=184447 loops=3)
-> Parallel Seq Scan on subcontributions (cost=0.00..6294.95 rows=325495 width=9) (actual time=0.002..6.771 rows=184447 loops=3)
-> Memoize (cost=0.44..0.84 rows=1 width=5) (actual time=0.000..0.000 rows=1 loops=553341)
Cache Key: subcontributions.contribution_id
Cache Mode: logical
Hits: 123894 Misses: 44462 Evictions: 0 Overflows: 0 Memory Usage: 4690kB
Worker 0: Hits: 142773 Misses: 49442 Evictions: 0 Overflows: 0 Memory Usage: 5215kB
Worker 1: Hits: 142496 Misses: 50274 Evictions: 0 Overflows: 0 Memory Usage: 5303kB
-> Index Scan using pk_contributions on contributions contributions_1 (cost=0.43..0.83 rows=1 width=5) (actual time=0.001..0.001 rows=1 loops=144178)
Index Cond: (id = subcontributions.contribution_id)
-> Parallel Hash (cost=5715.98..5715.98 rows=248398 width=5) (actual time=20.697..20.698 rows=198719 loops=3)
Buckets: 262144 Batches: 4 Memory Usage: 7936kB
-> Parallel Seq Scan on sessions (cost=0.00..5715.98 rows=248398 width=5) (actual time=0.003..7.165 rows=198719 loops=3)
Planning Time: 1.446 ms
Execution Time: 161571.400 ms
(52 rows)
[text/x-log] 15.log (6.5K, 3-15.log)
download | inline:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=433938.40..433938.41 rows=1 width=8) (actual time=1324.805..1384.694 rows=1 loops=1)
-> Gather (cost=433938.19..433938.40 rows=2 width=8) (actual time=1323.712..1384.690 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Partial Aggregate (cost=432938.19..432938.20 rows=1 width=8) (actual time=1322.444..1322.455 rows=1 loops=3)
-> Parallel Hash Join (cost=347888.29..430918.53 rows=807861 width=4) (actual time=1135.831..1287.886 rows=1523232 loops=3)
Hash Cond: (attachments.folder_id = folders.id)
-> Parallel Seq Scan on attachments (cost=0.00..54689.63 rows=1975074 width=8) (actual time=0.015..74.821 rows=1576685 loops=3)
Filter: (NOT is_deleted)
Rows Removed by Filter: 327767
-> Parallel Hash (cost=338919.45..338919.45 rows=546627 width=4) (actual time=988.970..988.979 rows=1030633 loops=3)
Buckets: 262144 Batches: 16 Memory Usage: 9664kB
-> Parallel Hash Join (cost=222930.79..338919.45 rows=546627 width=4) (actual time=862.438..942.550 rows=1030633 loops=3)
Hash Cond: (folders.event_id = events.id)
-> Parallel Hash Left Join (cost=199218.52..306522.55 rows=623482 width=8) (actual time=647.388..774.130 rows=1058109 loops=3)
Hash Cond: (folders.contribution_id = contributions.id)
Filter: (NOT COALESCE(sessions.is_deleted, contributions.is_deleted, subcontributions.is_deleted, false))
Rows Removed by Filter: 6434
-> Parallel Hash Left Join (cost=93909.23..175314.98 rows=1246964 width=14) (actual time=351.134..404.342 rows=1064544 loops=3)
Hash Cond: (folders.session_id = sessions.id)
-> Parallel Hash Left Join (cost=84126.27..146673.74 rows=1246964 width=17) (actual time=217.466..279.889 rows=1064544 loops=3)
Hash Cond: (folders.subcontribution_id = subcontributions.id)
Filter: ((contributions_1.is_deleted IS NULL) OR (NOT contributions_1.is_deleted))
Rows Removed by Filter: 157
-> Parallel Seq Scan on folders (cost=0.00..40289.07 rows=1331373 width=20) (actual time=0.016..59.322 rows=1064701 loops=3)
Filter: ((NOT is_deleted) AND (link_type <> 1))
Rows Removed by Filter: 4424
-> Parallel Hash (cost=78785.58..78785.58 rows=325495 width=6) (actual time=103.535..103.536 rows=184447 loops=3)
Buckets: 262144 Batches: 4 Memory Usage: 7488kB
-> Nested Loop Left Join (cost=0.44..78785.58 rows=325495 width=6) (actual time=0.030..90.520 rows=184447 loops=3)
-> Parallel Seq Scan on subcontributions (cost=0.00..6246.95 rows=325495 width=9) (actual time=0.002..6.298 rows=184447 loops=3)
-> Memoize (cost=0.44..0.84 rows=1 width=5) (actual time=0.000..0.000 rows=1 loops=553341)
Cache Key: subcontributions.contribution_id
Cache Mode: logical
Hits: 135333 Misses: 47817 Evictions: 0 Overflows: 0 Memory Usage: 4904kB
Worker 0: Hits: 136389 Misses: 48426 Evictions: 0 Overflows: 0 Memory Usage: 4966kB
Worker 1: Hits: 137268 Misses: 48108 Evictions: 0 Overflows: 0 Memory Usage: 4933kB
-> Index Scan using pk_contributions on contributions contributions_1 (cost=0.43..0.83 rows=1 width=5) (actual time=0.001..0.001 rows=1 loops=144351)
Index Cond: (id = subcontributions.contribution_id)
-> Parallel Hash (cost=5706.98..5706.98 rows=248398 width=5) (actual time=17.667..17.667 rows=198719 loops=3)
Buckets: 262144 Batches: 4 Memory Usage: 7936kB
-> Parallel Seq Scan on sessions (cost=0.00..5706.98 rows=248398 width=5) (actual time=0.003..7.229 rows=198719 loops=3)
-> Parallel Hash (cost=61434.91..61434.91 rows=2674191 width=5) (actual time=184.109..184.109 rows=2139359 loops=3)
Buckets: 262144 Batches: 64 Memory Usage: 6048kB
-> Parallel Seq Scan on contributions (cost=0.00..61434.91 rows=2674191 width=5) (actual time=0.009..83.995 rows=2139359 loops=3)
-> Parallel Hash (cost=14575.53..14575.53 rows=556859 width=4) (actual time=38.855..38.855 rows=444370 loops=3)
Buckets: 262144 Batches: 16 Memory Usage: 5344kB
-> Parallel Seq Scan on events (cost=0.00..14575.53 rows=556859 width=4) (actual time=0.008..18.893 rows=444370 loops=3)
Filter: (NOT is_deleted)
Rows Removed by Filter: 63752
Planning Time: 1.354 ms
Execution Time: 1385.414 ms
(52 rows)
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: tomas@vondra.me, adrian.moennich@cern.ch, andres@anarazel.de, pgsql-bugs@lists.postgresql.org, tv@fuzzy.cz, thomas.munro@gmail.com
Subject: Re: BUG #19449: Massive performance degradation for complex query on Postgres 16+ (few seconds -> multiple hours)
In-Reply-To: <2747373b-d188-43b1-8e49-66f9e23e3c24@vondra.me>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox