Обсуждение: BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10

The following bug has been logged on the website:

Bug reference:      18177
Logged by:          Robert Leach
Email address:      rleach@princeton.edu
PostgreSQL version: 13.12
Operating system:   macOS and linux
Description:

We upgraded our Django on a large project from 3.2 to 4.2 (and postgres from
10 to 13) and found that our test suite which typically took about 25-30
minutes roughly doubled in running time (50 to 75 minutes).  Switching back
to Django 3.2 but keeping postgres 13 also experiences the same slow-down.
I isolated one test that normally took 90s that now takes consistently 400s
and further narrowed it down to a single (simple) query.  That test would
run fast if run by itself, but it run after a series of other tests, would
take 400s.

I extracted the SQL generated for the query and performed an `explain` on
it, and it showed that the actual time took way longer than the estimated
cost.  Doing a vacuum full analyze was able to restore the speed, but the
only place where I was able to use it to get the speed back, relatively
caused weird errors in other tests.

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:

```
('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',)
```

There is a thread on the Django forum with lots of other details, but at the
outset of that discussion, I didn't even know what was causing the speed
issue.  For all I knew, it was some other change to our code, but with the
help of the folks in the Django forum, I think that this is conclusively due
to postgres 13.

https://forum.djangoproject.com/t/test-time-doubled-after-django-3-2-4-2-and-postgres-10-13-update/24843/16

If this is a known issue, is there a version of postgres (after v13) that
resolves it?

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.

David

Thanks David,

I very much appreciate your time and assessment.  I feel like I'm stuck, so all suggestions are very much welcome.

>> 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.

If this is operating as intended, there are a couple questions I have:

1. In postgres 10, the query always runs in under 1 second, regardless of the context.  In postgres 13, depending on
thecontext, why does it almost always takes over 200 seconds? 
2. In postgres 13, the query runs in under 1 second if I run just the one test that (starting from an empty database)
loadsdata and runs the query.  BUT, if I run that one test after having run tests in another python/django test class
(whichloads data, runs various tests, then destroys all the data that that test class loaded), that query takes over
200seconds to run.  Why would that be? 

I understand that the above involves variables unrelated to postgres (i.e. Django test classes), but if the only thing
Ichange is postgres (v10 versus v13), v10 is always fast and v13 has this context-dependent slowness and I have not
beenable to find a problem in the python code after having investigated this now for a week and a half. 

We have been endeavoring to keep our code database-architecture-independent, and as far as I understand the suggestions
madeby the Django folks, it seems like running the vacuum command in key places is potentially a strategy to deal with
thisissue (even though I haven't been able to get it to consistently work yet), but doing that would tie the codebase
toa particular database architecture.  Are there alternate solutions that do not involve altering our Django codebase? 

> Has autovacuum gotten to this table recently?


I only just learned the other day about the "VACUUM FULL ANALYZE" command and have been trying to manually run it at
differentpoints with mixed outcomes WRT speed.  I don't know what the difference between that and "autovacuum" is. 

> select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass;

When I try to execute this command, I get:

psycopg2.errors.UndefinedTable: relation "DataRepo_peakdata" does not exist

Maybe I'm not running it in the correct location?  Or I'm running it too many times?

> 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.

How do I determine that?  Also, I have tried inserting `vacuum full analyze` commands at different points in the code,
andit doesn't appear to consistently speed things up.  In fact, before I started attempting vacuuming, there are
occasionalinstances where it randomly ran fast without me changing anything, i.e. the problem intermittently goes away.
Though like I said, I've been working on solving this for a week and a half, so I could be mistaken.  I've tried so
manythings and I have been switching back to v10 occasionally, so it could be that I was on v10, thinking I was on v13
whenI saw it run fast. 

> For the future, it might be best to post EXPLAIN output as an
> attachment.  The extra formatting makes it difficult to read.

Sorry about that.  I used the web form and there wasn't at attachment field.

Rob

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.gmail.com


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Fri, 3 Nov 2023 at 09:04, Robert Leach <rleach@princeton.edu> wrote:
> > Nothing looks particularly bug like so far.  It seems the
> > pg_class.reltuples estimate for this relation is way out.
>
> If this is operating as intended, there are a couple questions I have:
>
> 1. In postgres 10, the query always runs in under 1 second, regardless of the context.  In postgres 13, depending on
thecontext, why does it almost always takes over 200 seconds? 

The reason the query is slow is that the planner thinks that there's
only 1 row in the DataRepo_peakdata table. In reality, when you
executed that query there were 7896 rows.

Because the planner thinks there's 1 row. It opts to use the fastest
method available to join two relations where one side has just 1 row,
i.e. Nested Loop.  Unfortunately, it's a risky plan as
underestimations have quadratic repercussions.  In the v13 query, this
comes out at this point in the plan:

              ->  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)

You can see the planner thought the index scan would produce 1 row.
7896 were found during execution.

Most of the time of the entire query can be accounted for by this plan
fragment. The average execution time for 1 loop of that 2nd Nested
Loop quoted above is 25.621 milliseconds. If you multiply that number
by the number of loops (7896), you get 202303.416 milliseconds.

Because the scan on DataRepo_peakdata contains no clauses, the row
estimate here is derived from pg_class.reltuples for that index.
VACUUM and ANALYZE adjust this pg_class column after they run so that
the planner has a recent estimate on the number of records in the
table. The estimated tuples for a clause-less scan of an index don't
come directly from pg_class.reltuples.  What happens is it looks at
relpages and reltuples to calculate the average tuples per page then
we apply that average over the *current* number of pages in the index.

It would be interesting to see what pg_class reltuples and relpages is
set to for this index.

> 2. In postgres 13, the query runs in under 1 second if I run just the one test that (starting from an empty database)
loadsdata and runs the query.  BUT, if I run that one test after having run tests in another python/django test class
(whichloads data, runs various tests, then destroys all the data that that test class loaded), that query takes over
200seconds to run.  Why would that be? 

I don't know what these tests do.  If they update some data in the
tables then perhaps the index becomes bloated and that results in the
number of pages in the index changing which affects the estimate of
the number of tuples in the index.

It would be good to get the output of
pg_relation_size('DataRepo_peakdata_peak_group_id_4dd87f4a') before
and after the tests run.

> I understand that the above involves variables unrelated to postgres (i.e. Django test classes), but if the only
thingI change is postgres (v10 versus v13), v10 is always fast and v13 has this context-dependent slowness and I have
notbeen able to find a problem in the python code after having investigated this now for a week and a half. 

Going by your EXPLAIN output, I think we can confirm the problem is
the reltuples value that's calculated in PostgreSQL's
estimate_rel_size() function. It's just a question of finding out
*why* the reltuples value is not close to reality. An incorrect value
does not mean PostgreSQL bugs. Stale stats could be an explanation.
Let's dig further to find out.

> We have been endeavoring to keep our code database-architecture-independent, and as far as I understand the
suggestionsmade by the Django folks, it seems like running the vacuum command in key places is potentially a strategy
todeal with this issue (even though I haven't been able to get it to consistently work yet), but doing that would tie
thecodebase to a particular database architecture.  Are there alternate solutions that do not involve altering our
Djangocodebase? 

We need to find out the problem first.  Perhaps more aggressive
autovacuum settings could help, but we've not gotten far enough to
tell yet.

I suspect it's a case of the fact that running tests do a whole load
of database changes in a short space of time.  In this case, perhaps
that's just faster than autovacuum can react to those changes.

> > Has autovacuum gotten to this table recently?
>
>
> I only just learned the other day about the "VACUUM FULL ANALYZE" command and have been trying to manually run it at
differentpoints with mixed outcomes WRT speed.  I don't know what the difference between that and "autovacuum" is. 

Autovacuum will never do VACUUM FULL.   It'll do various forms of
VACUUM and also ANALYZE.

> > select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass;
>
> When I try to execute this command, I get:
>
> psycopg2.errors.UndefinedTable: relation "DataRepo_peakdata" does not exist

You'd need to be connected to the same database as that table exists
in.  Your EXPLAIN output had extra formatting in it. I had assumed the
quotes were there because the table was created with some upper-case
characters. PostgreSQL folds unquoted identifiers to lower-case.
Perhaps you can try without the quotes if you still get that when
connected to the correct database.

> > 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.
>
> How do I determine that?  Also, I have tried inserting `vacuum full analyze` commands at different points in the
code,and it doesn't appear to consistently speed things up.  In fact, before I started attempting vacuuming, there are
occasionalinstances where it randomly ran fast without me changing anything, i.e. the problem intermittently goes away.
Though like I said, I've been working on solving this for a week and a half, so I could be mistaken.  I've tried so
manythings and I have been switching back to v10 occasionally, so it could be that I was on v10, thinking I was on v13
whenI saw it run fast. 

Perhaps it goes away after autovacuum runs ANALYZE on the table again.
I suspect this problem depends on the timing of autovacuum and suspect
you might see the tests running faster more often if you changed
autovacuum_naptime to 1 second. You'd probably see them more
consistently running slower if you set autovacuum_naptime to some
value higher than it's set to right now.

David

> Perhaps more aggressive autovacuum settings could help, but we've not gotten far enough to tell yet.

Well, I can report that changing the autovacuum settings does indeed help.  I added this to all of the `setUpClass`
methodsof our test code: 

    ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0);
    ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000);
    ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0);
    ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000);

The one query I've been testing with reproducibly runs in a fraction of a second and when I run the entire test suite
ongithub, it runs in 33 minutes as opposed to an hour, which is close to on par with how it was running in postgres 10. 

It's also notable that I have not been able to get this speed improvement using a `VACUUM FULL ANALYZE`, though I can't
besure I ever did it correctly in the first place. 

The above was based on the feedback you guys provided and the following blog post:

    https://www.lob.com/blog/supercharge-your-postgresql-performance

I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a
specificdatabase.  I'm not sure if where I put it is the best place for it either.  Is there a config file I can put
thesesettings in? 

And I'm still curious why this wasn't necessary in postgres 10?

Rob

On Tue, 7 Nov 2023 at 11:17, Robert Leach <rleach@princeton.edu> wrote:
>     ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0);
>     ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000);
>     ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0);
>     ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000);
>
> I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a
specificdatabase.  I'm not sure if where I put it is the best place for it either.  Is there a config file I can put
thesesettings in?
 

You can apply those changes globally in postgresql.conf, but having
the autovacuum_vacuum_threshold / autovacuum_analyze_threshold set to
that constant is unlikely to be very good for all tables. Perhaps
there some scale_factor above 0.0 and below 0.2 that you can find that
makes it run fast.

> And I'm still curious why this wasn't necessary in postgres 10?

If you show us the output of the following two queries:

SELECT relname, reltuples,relpages,pg_relation_size(oid) from pg_class
where oid = '"DataRepo_peakdata"'::regclass;
select c.relname, c.reltuples, c.relpages, pg_relation_size(c.oid)
from pg_class c inner join pg_index i on c.oid=i.indexrelid where
i.indrelid = '"DataRepo_peakdata"'::regclass;

run directly before the query in question both on PG10 and on PG13
both when the query runs quickly and when it runs slowly.  We might
see something there that helps indicate what's going on.

David