Thread: too high planning time

too high planning time

From

Kenny Bachman

Date:

02 February 2023, 12:54:34

Hello Team,

I have a problem with the explain analyze' output of some queries. There is too high planning time, but the execution time is relatively low. What is the possible reason behind this problem? I also ran the vacuum and analyze commands for the table.

EXPLAIN ANALYZE select
i."DefinitionId",
from
"T_WF_INSTANCE" i
where
i."InstanceId" = 10045683193;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Index Scan using "T_WF_INSTANCE_InstanceId_ApplicationCd_EntityStatusCd_idx" on "T_WF_INSTANCE" i (cost=0.57..2.79 rows=1 width=34) (actual time=2.522..2.522 rows=1 loops=1)
Index Cond: ("InstanceId" = '10045683193'::bigint)
Planning Time: 8460.446 ms
Execution Time: 2.616 ms
(4 rows)

Thank you,

Kenny

Re: too high planning time

From

Tom Lane

Date:

02 February 2023, 18:24:25

Kenny Bachman <kenny.bachman17@gmail.com> writes:
> EXPLAIN ANALYZE select
>     i."DefinitionId",
> from
>     "T_WF_INSTANCE" i
> where
>     i."InstanceId" = 10045683193;

>        QUERY PLAN

>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Index Scan using
> "T_WF_INSTANCE_InstanceId_ApplicationCd_EntityStatusCd_idx" on
> "T_WF_INSTANCE" i  (cost=0.57..2.79 rows=1 width=34) (actual
> time=2.522..2.522 rows=1 loops=1)
>    Index Cond: ("InstanceId" = '10045683193'::bigint)

> * Planning Time: 8460.446 ms Execution Time: 2.616 ms*
> (4 rows)

It's hard to believe that such a simple query could take that
long to plan.  What I'm wondering is if the planner got blocked
on some other session's exclusive lock.  Not a lock on
"T_WF_INSTANCE" itself, because we'd have got that lock during
parsing before the "Planning Time" measurement starts.  But
there's going to be a physical access to the table's index
to determine its tree height, so an ex-lock on the index could
explain this.  Or an ex-lock on catalogs, particularly pg_statistic.
What else is going on in your database when this happens?

            regards, tom lane

Re: too high planning time

From

Kenny Bachman

Date:

02 February 2023, 21:21:54

In fact, when I run the query for the second time, it returns very fast results. But after a while the problem reoccurs.

Not just for these queries, but almost all queries in the database are slowed down this way.

Is it normal to have a lock on the catalog or system tables? What should I do when this happens on pg_statistic or other catalogs?

thanks a lot for your comments and help

Kenny

Tom Lane <tgl@sss.pgh.pa.us>, 2 Şub 2023 Per, 18:24 tarihinde şunu yazdı:

Kenny Bachman <kenny.bachman17@gmail.com> writes:
> EXPLAIN ANALYZE select
> i."DefinitionId",
> from
> "T_WF_INSTANCE" i
> where
> i."InstanceId" = 10045683193;

> QUERY PLAN

> --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Index Scan using
> "T_WF_INSTANCE_InstanceId_ApplicationCd_EntityStatusCd_idx" on
> "T_WF_INSTANCE" i (cost=0.57..2.79 rows=1 width=34) (actual
> time=2.522..2.522 rows=1 loops=1)
> Index Cond: ("InstanceId" = '10045683193'::bigint)

> * Planning Time: 8460.446 ms Execution Time: 2.616 ms*
> (4 rows)

It's hard to believe that such a simple query could take that
long to plan. What I'm wondering is if the planner got blocked
on some other session's exclusive lock. Not a lock on
"T_WF_INSTANCE" itself, because we'd have got that lock during
parsing before the "Planning Time" measurement starts. But
there's going to be a physical access to the table's index
to determine its tree height, so an ex-lock on the index could
explain this. Or an ex-lock on catalogs, particularly pg_statistic.
What else is going on in your database when this happens?

regards, tom lane

Re: too high planning time

From

Ron

Date:

02 February 2023, 21:57:04

pg_stat_activity is the place to look.

This tells you all of the blocked pids:
SELECT pid
     , username
     , pg_blocking_pids(pid) AS blocked_by
     , left(query, 100) as blocked_query
FROM pg_stat_activity
WHERE CARDINALITY(blocking_pids(pid)) > 0;

From there, you can see what the blocking pid is doing.

On 2/2/23 12:21, Kenny Bachman wrote:

In fact, when I run the query for the second time, it returns very fast results. But after a while the problem reoccurs.
Not just for these queries, but almost all queries in the database are slowed down this way.
Is it normal to have a lock on the catalog or system tables? What should I do when this happens on pg_statistic or other catalogs?

thanks a lot for your comments and help
Kenny

Tom Lane <tgl@sss.pgh.pa.us>, 2 Şub 2023 Per, 18:24 tarihinde şunu yazdı:
Kenny Bachman <kenny.bachman17@gmail.com> writes:
> EXPLAIN ANALYZE select
> i."DefinitionId",
> from
> "T_WF_INSTANCE" i
> where
> i."InstanceId" = 10045683193;

> QUERY PLAN

> --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Index Scan using
> "T_WF_INSTANCE_InstanceId_ApplicationCd_EntityStatusCd_idx" on
> "T_WF_INSTANCE" i (cost=0.57..2.79 rows=1 width=34) (actual
> time=2.522..2.522 rows=1 loops=1)
> Index Cond: ("InstanceId" = '10045683193'::bigint)

> * Planning Time: 8460.446 ms Execution Time: 2.616 ms*
> (4 rows)

It's hard to believe that such a simple query could take that
long to plan. What I'm wondering is if the planner got blocked
on some other session's exclusive lock. Not a lock on
"T_WF_INSTANCE" itself, because we'd have got that lock during
parsing before the "Planning Time" measurement starts. But
there's going to be a physical access to the table's index
to determine its tree height, so an ex-lock on the index could
explain this. Or an ex-lock on catalogs, particularly pg_statistic.
What else is going on in your database when this happens?

regards, tom lane

--
Born in Arizona, moved to Babylonia.