From: Tomas Vondra <tomas.vondra@enterprisedb.com>
To: David Rowley <dgrowleyml@gmail.com>
To: rleach@princeton.edu
To: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10
Date: Thu, 2 Nov 2023 23:00:00 +0100
Message-ID: <e61a37f3-eeeb-21cb-647d-0fc3771f94c9@enterprisedb.com> (raw)
In-Reply-To: <CAApHDvrRgDpV19MDNZ-0Tou-F2+cTU6ZNPq3rixUGp_kuw6-9Q@mail.gmail.com>
References: <18177-a282c2eaaf791f21@postgresql.org>
<CAApHDvrRgDpV19MDNZ-0Tou-F2+cTU6ZNPq3rixUGp_kuw6-9Q@mail.gmail.com>
On 11/2/23 11:45, David Rowley wrote:
> On Thu, 2 Nov 2023 at 21:56, PG Bug reporting form
> <noreply@postgresql.org> wrote:
>> I cannot claim to understand the bug that is causing this issue, so the best
>> I can do is simply provide the explain output and try to keep from providing
>> confusing details, because this is outside the realm of my expertise:
>
>
>> (' -> Index Scan using
>> "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata"
>> (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896
>> loops=1)',)
>
> Nothing looks particularly bug like so far. It seems the
> pg_class.reltuples estimate for this relation is way out.
>
> Has autovacuum gotten to this table recently?
>
> select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass;
>
> The plan would likely come good if you analyzed that table. You
> should see if you can figure out why autovacuum hasn't analyzed it.
>
> For the future, it might be best to post EXPLAIN output as an
> attachment. The extra formatting makes it difficult to read.
>
I did look at the django forum, and the plans are there. For convenience
I'm attaching them here too. But there's nothing particularly revealing,
except that it indeed seems to be related to the index scan.
One thing that puzzles me is why it'd behave differently between PG10
and PG13. I'd have expected both releases to do the same thing if there
are no stats, but maybe PG10 does analyze it time for some reason?
Would be interesting to see the pg_class data (reltuples, relpages and
timestamp of last analyze/autoanalyze) for the slow/fast cases.
However, the forum thread also claims this:
And here is the Django 4.2 and postgres 13 output when running just
the one test (which is always fast):
Which seems weird. But maybe the table is modified/updated by the tests,
so a single test might seem much less data, or something? Not sure.
However, there's one more interesting bit - the 'weird errors' after
placing VACUUM FULL ANALYZE into test setup/teardown are this:
psycopg2.errors.DataCorrupted: missing chunk number 0 for toast
value 2884552 in pg_toast_2619
That seems unrelated to the planning issue, but it definitely seems like
a bug. Interestingly enough we got a report [1] about the same error on
pgsql-hackers a couple days ago. That error affected PG11-16, which
seems to be consistent with this (PG13).
[1]
https://www.postgresql.org/message-id/CALdSSPhmqoN02ciT4UxS6ax0N84NpRwPWm87nKJ_%2B0G-Na8qOQ%40mail.g...
regards
--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Attachments:explains.txt (text/plain, 6.4K) download
Aggregate (cost=45.77..45.78 rows=1 width=8) (actual time=202326.210..202326.214 rows=1 loops=1)
-> Unique (cost=0.88..45.76 rows=1 width=1052) (actual time=10492.963..202326.205 rows=1 loops=1)
-> Nested Loop (cost=0.88..45.75 rows=1 width=1052) (actual time=10492.959..202326.188 rows=8 loops=1)
Join Filter: ("DataRepo_peakdata".id = "DataRepo_peakdatalabel".peak_data_id)
Rows Removed by Join Filter: 3076
-> Nested Loop (cost=0.62..37.47 rows=1 width=8) (actual time=10492.455..202323.935 rows=8 loops=1)
Join Filter: ("DataRepo_peakgroup".id = "DataRepo_peakdata".peak_group_id)
Rows Removed by Join Filter: 7888
-> Index Scan using "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 loops=1)
-> Nested Loop (cost=0.38..29.20 rows=1 width=4) (actual time=2.942..25.621 rows=1 loops=7896)
Join Filter: ("DataRepo_peakgroup".peak_annotation_file_id = "DataRepo_archivefile".id)
-> Nested Loop (cost=0.38..18.43 rows=1 width=8) (actual time=2.935..25.614 rows=1 loops=7896)
Join Filter: ("DataRepo_msrun".sample_id = "DataRepo_sample".id)
Rows Removed by Join Filter: 83
-> Nested Loop (cost=0.12..10.15 rows=1 width=12) (actual time=0.028..2.513 rows=84 loops=7896)
Join Filter: ("DataRepo_peakgroup".msrun_id = "DataRepo_msrun".id)
Rows Removed by Join Filter: 3486
-> Index Scan using "DataRepo_peakgroup_peak_annotation_file_id_6dc2fc25" on "DataRepo_peakgroup" (cost=0.12..8.14 rows=1 width=12) (actual time=0.006..0.464 rows=84 loops=7896)
Filter: ((name)::text = 'serine'::text)",)
Rows Removed by Filter: 1008
-> Seq Scan on "DataRepo_msrun" (cost=0.00..2.00 rows=1 width=8) (actual time=0.013..0.017 rows=42 loops=663264)
-> Index Scan using "DataRepo_sample_pkey" on "DataRepo_sample" (cost=0.25..8.27 rows=1 width=4) (actual time=0.194..0.275 rows=1 loops=663264)
Filter: ((name)::text = 'xzl5_panc'::text)",)
Rows Removed by Filter: 281
-> Seq Scan on "DataRepo_archivefile" (cost=0.00..10.75 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=7896)
Filter: ((filename)::text = 'alafasted_cor.xlsx'::text)",)
-> Index Scan using "DataRepo_peakdatalabel_peak_data_id_f6151d4a" on "DataRepo_peakdatalabel" (cost=0.25..8.27 rows=1 width=12) (actual time=0.007..0.217 rows=386 loops=8)
Filter: ((element)::text = 'C'::text)",)
Rows Removed by Filter: 180
Planning Time: 0.963 ms
Execution Time: 202327.334 ms
Aggregate (cost=99.01..99.02 rows=1 width=8) (actual time=1.399..1.403 rows=1 loops=1)
-> Unique (cost=98.99..99.00 rows=1 width=1052) (actual time=1.390..1.398 rows=1 loops=1)
-> Sort (cost=98.99..99.00 rows=1 width=1052) (actual time=1.389..1.393 rows=8 loops=1)
Sort Key: "DataRepo_peakgroup".id
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=5.36..98.98 rows=1 width=1052) (actual time=0.261..1.377 rows=8 loops=1)
-> Nested Loop (cost=5.08..80.19 rows=51 width=8) (actual time=0.152..1.234 rows=8 loops=1)
-> Nested Loop (cost=0.55..28.36 rows=1 width=4) (actual time=0.138..1.214 rows=1 loops=1)
-> Nested Loop (cost=0.29..27.20 rows=1 width=8) (actual time=0.061..0.873 rows=84 loops=1)
-> Nested Loop (cost=0.14..18.92 rows=1 width=8) (actual time=0.048..0.667 rows=84 loops=1)
-> Seq Scan on "DataRepo_archivefile" (cost=0.00..10.75 rows=1 width=4) (actual time=0.011..0.012 rows=1 loops=1)
Filter: ((filename)::text = 'alafasted_cor.xlsx'::text)",)
-> Index Scan using "DataRepo_peakgroup_peak_annotation_file_id_6dc2fc25" on "DataRepo_peakgroup" (cost=0.14..8.16 rows=1 width=12) (actual time=0.035..0.634 rows=84 loops=1)
Index Cond: (peak_annotation_file_id = "DataRepo_archivefile".id)
Filter: ((name)::text = 'serine'::text)",)
Rows Removed by Filter: 1008
-> Index Scan using "DataRepo_msrun_pkey" on "DataRepo_msrun" (cost=0.14..8.16 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=84)
Index Cond: (id = "DataRepo_peakgroup".msrun_id)
-> Index Scan using "DataRepo_sample_pkey" on "DataRepo_sample" (cost=0.27..0.72 rows=1 width=4) (actual time=0.004..0.004 rows=0 loops=84)
Index Cond: (id = "DataRepo_msrun".sample_id)
Filter: ((name)::text = 'xzl5_panc'::text)",)
Rows Removed by Filter: 1
-> Bitmap Heap Scan on "DataRepo_peakdata" (cost=4.52..51.52 rows=31 width=8) (actual time=0.010..0.012 rows=8 loops=1)
Recheck Cond: (peak_group_id = "DataRepo_peakgroup".id)
Heap Blocks: exact=1
-> Bitmap Index Scan on "DataRepo_peakdata_peak_group_id_4dd87f4a" (cost=0.00..4.51 rows=31 width=0) (actual time=0.005..0.005 rows=8 loops=1)
Index Cond: (peak_group_id = "DataRepo_peakgroup".id)
-> Index Only Scan using unique_peakdata on "DataRepo_peakdatalabel" (cost=0.29..0.37 rows=1 width=12) (actual time=0.017..0.017 rows=1 loops=8)
Index Cond: ((peak_data_id = "DataRepo_peakdata".id) AND (element = \'C\'::text))
Heap Fetches: 8
Planning Time: 1.195 ms
Execution Time: 1.566 ms
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@enterprisedb.com, dgrowleyml@gmail.com, rleach@princeton.edu, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10
In-Reply-To: <e61a37f3-eeeb-21cb-647d-0fc3771f94c9@enterprisedb.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox