Re: BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10 - Mailing list pgsql-bugs

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.

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 the context, 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) loads data and runs the query.  BUT, if I run that one test after having run tests in another python/django test class (which loads data, runs various tests, then destroys all the data that that test class loaded), that query takes over 200 seconds 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.

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.