Re: RFC: Logging plan of the running query

On Mon, Feb 12, 2024 at 12:42 PM Ashutosh Bapat
<ashutosh(dot)bapat(dot)oss(at)gmail(dot)com> wrote:
>
> On Mon, Feb 12, 2024 at 5:31 AM jian he <jian(dot)universality(at)gmail(dot)com> wrote:
> >
> > On Wed, Feb 7, 2024 at 12:58 PM Ashutosh Bapat
> > <ashutosh(dot)bapat(dot)oss(at)gmail(dot)com> wrote:
> > >
> > > >
> > > > > */
> > > > > How bad this performance could be. Let's assume that a query is taking
> > > > > time and pg_log_query_plan() is invoked to examine the plan of this
> > > > > query. Is it possible that the looping over all the locks itself takes
> > > > > a lot of time delaying the query execution further?
> > > >
> > corner case test:
> > pgbench --initialize --partition-method=range --partitions=20000
> > Somehow my setup, the pg_bench didn't populate the data but there are
> > 20000 partitions there.
> > (all my other settings are default)
> >
> > some interesting things happened when a query touch so many partitions like:
> > select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1;
> >
> > in another session, if you immediate call SELECT pg_log_query_plan(9482);
> > then output be
> > `
> > LOG: backend with PID 9482 is not running a query or a subtransaction
> > is aborted
> > `
> > however if you delay a little bit of time (like 1 second), then
> > LOG will emit the plan with lots of text (not sure the plan is right).
> >
> > I think the reason is that the `InitPlan` within
> > standard_ExecutorStart takes more time to finish
> > when your query touches a lot of partitions.
>
> That's probably expected unless we make the ActiveQueryDesc available
> before ExecutorRun.

so the error message should be something like:
errmsg("backend with PID %d is not running a query or a subtransaction
is aborted or the plan is not generated",

>
> How much time did it took between issuing SELECT
> pg_log_query_plan(9482); and plan getting output to the server error
> logs?

it either says errmsg("backend with PID %d is not running a query,.....)
or outputs the plan immediately, if i wait one or two seconds to call
pg_log_query_plan.

because of previously mentioned: with lots of partitions, initplan
took longer to finish.
setup: 2 sessions, one runs the query (select abalance, aid from
public.pgbench_accounts,pg_sleep(4) where aid > 1;),
another one calls pg_log_query_plan.