Thread: Slow planning, fast execution for particular 3-table query

On Mon, 2019-11-04 at 03:04 +0000, David Wheeler wrote:
> We’re having trouble working out why the planning time for this particular query is slow
> (~2.5s vs 0.9ms execution time). As you can see below, there are only 3 tables involved
> so it’s hard to imagine what decisions the planner has to make that take so long. After
> 5 runs the prepared-statement code kicks in and it becomes quick, but it’s quite
> infuriating for the first 5 runs given the execution is so much faster. 
> 
> Are you able to give any tips what might be taking so long (and how we might improve it)?
> 
[...]
> Planning time: 2429.682 ms
> 
> Execution time: 0.914 ms

Strange.
Are any of your catalog tables unusually large?

SELECT pg_relation_size(t.oid),
       t.relname
FROM pg_class AS t
   JOIN pg_namespace AS n ON t.relnamespace = n.oid
WHERE t.relkind = 'r'
ORDER BY pg_relation_size(t.oid) DESC
LIMIT 10;

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

I'm not sure what "unusually large" is, but they're all < 1mb which is a little larger than some of our other
comparabledatabases (mostly <300kb) but seems reasonable to me. 
 

Regards, 
 
David

On 4/11/19, 3:37 pm, "Laurenz Albe" <laurenz.albe@cybertec.at> wrote:

    On Mon, 2019-11-04 at 03:04 +0000, David Wheeler wrote:
    > We’re having trouble working out why the planning time for this particular query is slow
    > (~2.5s vs 0.9ms execution time). As you can see below, there are only 3 tables involved
    > so it’s hard to imagine what decisions the planner has to make that take so long. After
    > 5 runs the prepared-statement code kicks in and it becomes quick, but it’s quite
    > infuriating for the first 5 runs given the execution is so much faster. 
    > 
    > Are you able to give any tips what might be taking so long (and how we might improve it)?
    > 
    [...]
    > Planning time: 2429.682 ms
    > 
    > Execution time: 0.914 ms
    
    Strange.
    Are any of your catalog tables unusually large?
    
    SELECT pg_relation_size(t.oid),
           t.relname
    FROM pg_class AS t
       JOIN pg_namespace AS n ON t.relnamespace = n.oid
    WHERE t.relkind = 'r'
    ORDER BY pg_relation_size(t.oid) DESC
    LIMIT 10;
    
    Yours,
    Laurenz Albe
    -- 
    Cybertec | https://www.cybertec-postgresql.com
    
    

David Wheeler wrote:
> I'm not sure what "unusually large" is, but they're all < 1mb which is a little larger
> than some of our other comparable databases (mostly <300kb) but seems reasonable to me. 

I forgot the condition "AND n.nspname = 'pg_catalog'"...

But if all your tables are small, catalog bloat is probably not your problem.

Do you have many tables in the database? Partitioning?

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

David Wheeler <dwheeler@dgitsystems.com> writes:
> We’re having trouble working out why the planning time for this
> particular query is slow (~2.5s vs 0.9ms execution time). As you can see
> below, there are only 3 tables involved so it’s hard to imagine what
> decisions the planner has to make that take so long.

I wonder whether this traces to the cost of trying to estimate the
largest/smallest value of an indexed column by looking into the index.
Normally that's pretty cheap, but if you have a lot of recently-inserted
or recently-deleted values at the end of the index, it can get painful.
AFAIR this only happens for columns that are equijoin keys, so the fact
that your query is a join is significant.

I'm not convinced that this is the problem, because it's a corner case
that few people hit.  To see this issue, you have to have recently
inserted or deleted a bunch of extremal values of the indexed join-key
column.  And the problem only persists until those values become known
committed-good, or known dead-to-everybody.  (Maybe you've got a
long-running transaction somewhere, postponing the dead-to-everybody
condition?)

> Postgres version 9.5.19

If this *is* the cause, v11 and up have a performance improvement that
you need:

https://git.postgresql.org/gitweb/?p=postgresql.git&a=commitdiff&h=3ca930fc3

            regards, tom lane

>    To see this issue, you have to have recently
>    inserted or deleted a bunch of extremal values of the indexed join-key
>    column.  And the problem only persists until those values become known
>    committed-good, or known dead-to-everybody.  (Maybe you've got a
>    long-running transaction somewhere, postponing the dead-to-everybody
>    condition?)

There are no long-running transactions that have backend_xmin set in pg_stat_activity, if that's what you mean here.
Thereare also no open prepared transactions or replication slots which I understand have a similar keeping-things-alive
issue.
 

These tables are biggish (hundreds of mb), but not changing so frequently that I'd expect large quantities of data to
beinserted or deleted before autovac can get in there and clean it up. And certainly not in a single uncommitted
transaction.
 

I'll try reindexing each of the tables just to make sure it's not strange index imbalance or something causing the
issue.
 

Regards, 
 
David

On 4/11/19, 4:01 pm, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:

    David Wheeler <dwheeler@dgitsystems.com> writes:
    > We’re having trouble working out why the planning time for this
    > particular query is slow (~2.5s vs 0.9ms execution time). As you can see
    > below, there are only 3 tables involved so it’s hard to imagine what
    > decisions the planner has to make that take so long.
    
    I wonder whether this traces to the cost of trying to estimate the
    largest/smallest value of an indexed column by looking into the index.
    Normally that's pretty cheap, but if you have a lot of recently-inserted
    or recently-deleted values at the end of the index, it can get painful.
    AFAIR this only happens for columns that are equijoin keys, so the fact
    that your query is a join is significant.
    
    I'm not convinced that this is the problem, because it's a corner case
    that few people hit.  To see this issue, you have to have recently
    inserted or deleted a bunch of extremal values of the indexed join-key
    column.  And the problem only persists until those values become known
    committed-good, or known dead-to-everybody.  (Maybe you've got a
    long-running transaction somewhere, postponing the dead-to-everybody
    condition?)
    
    > Postgres version 9.5.19
    
    If this *is* the cause, v11 and up have a performance improvement that
    you need:
    
    https://git.postgresql.org/gitweb/?p=postgresql.git&a=commitdiff&h=3ca930fc3
    
                regards, tom lane
    

On Mon, Nov 04, 2019 at 03:04:45AM +0000, David Wheeler wrote:
> Postgres version 9.5.19
> Each of the tables has between 3-4 indexes, and all the indexes include tid as first parameter.

On Mon, Nov 04, 2019 at 12:00:59AM -0500, Tom Lane wrote:
> If this *is* the cause, v11 and up have a performance improvement that
> you need:

But note that index definition will be prohibited since:

https://www.postgresql.org/docs/9.6/release-9-6.html
|Disallow creation of indexes on system columns, except for OID columns (David Rowley)
|Such indexes were never considered supported, and would very possibly misbehave since the system might change the
system-columnfields of a tuple without updating indexes. However, previously there were no error checks to prevent them
frombeing created.
 

Justin

On Thu, 7 Nov 2019 at 11:59, Justin Pryzby <pryzby@telsasoft.com> wrote:
>
> On Mon, Nov 04, 2019 at 03:04:45AM +0000, David Wheeler wrote:
> > Postgres version 9.5.19
> > Each of the tables has between 3-4 indexes, and all the indexes include tid as first parameter.


> But note that index definition will be prohibited since:
>
> https://www.postgresql.org/docs/9.6/release-9-6.html
> |Disallow creation of indexes on system columns, except for OID columns (David Rowley)
> |Such indexes were never considered supported, and would very possibly misbehave since the system might change the
system-columnfields of a tuple without updating indexes. However, previously there were no error checks to prevent them
frombeing created. 

David will have meant the user column named "tid" rather than the
system column named "ctid".

--
 David Rowley                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Thu, Nov 07, 2019 at 01:15:30PM +1300, David Rowley wrote:
> On Thu, 7 Nov 2019 at 11:59, Justin Pryzby <pryzby@telsasoft.com> wrote:
> >
> > On Mon, Nov 04, 2019 at 03:04:45AM +0000, David Wheeler wrote:
> > > Postgres version 9.5.19
> > > Each of the tables has between 3-4 indexes, and all the indexes include tid as first parameter.
> 
> > But note that index definition will be prohibited since:
> >
> > https://www.postgresql.org/docs/9.6/release-9-6.html
> > |Disallow creation of indexes on system columns, except for OID columns (David Rowley)
> > |Such indexes were never considered supported, and would very possibly misbehave since the system might change the
system-columnfields of a tuple without updating indexes. However, previously there were no error checks to prevent them
frombeing created.
 
> 
> David will have meant the user column named "tid" rather than the
> system column named "ctid".

Ah.  And David must have meant David W :)

Justin