Re: RFC: Logging plan of the running query

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.

How much time did it took between issuing SELECT
pg_log_query_plan(9482); and plan getting output to the server error
logs? How does this time compare with say the same time difference for
a simple query and how much of that time can be attributed to Lock
table hash scan, if the difference between time difference is huge.

--
Best Wishes,
Ashutosh Bapat