Re: RFC: Logging plan of the running query

On Thu, Nov 9, 2023 at 4:56 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-11-09 16:11, Ashutosh Bapat wrote:
> > On Thu, Nov 9, 2023 at 12:03 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> > wrote:
> >> >>
> >> >> 1. When a backend is running nested queries, we will see the plan of
> >> >> the innermost query. That query may not be the actual culprit if the
> >> >> user query is running slowly. E.g a query being run as part of inner
> >> >> side nested loop when the nested loop itself is the bottleneck. I
> >> >> think it will be useful to print plans of all the whole query stack.
> >>
> >> This was discussed in previous threads[1] and we thought it'd be
> >> useful
> >> but since it needed some extra works, we stopped widening the scope.
> >>
> >> >
> >> > I think we can start with what auto_explain is doing. Always print the
> >> > plan of the outermost query; the query found in pg_stat_activity. In a
> >> > later version we might find a way to print plans of all the queries in
> >> > the stack and do so in a readable manner.
> >>
> >> Agreed there are cases printing plan of the outermost query is more
> >> useful.
> >>
> >
> > I am fine printing the plan of the outermost query. This will help
> > many cases. Printing plans of the whole query stack can be added as an
> > add on later.
> >
> >> >
> >> > This makes tracking activeQueryDesc a bit tricky. My guess is that the
> >> > outermost query's descriptor will be available through ActivePortal
> >> > most of the time. But there are cases when ExecutorRun is called by
> >> > passing a queryDesc directly. So may be there are some cases where
> >> > that's not true.
> >>
> >> Yeah, actually the original version of the patch got the plan from
> >> ActivePortal, but it failed logging plan when the query was something
> >> like this[2]:
> >>
> >> DO $$
> >> BEGIN
> >> PERFORM pg_sleep(100);
> >> END$$;
> >
> > References [1] and [2] are not listed in your email.
>
> Oops, sorry. Here are links:
>
> [1]
> https://www.postgresql.org/message-id/64f716c44629e303b66e6c24502147cc%40oss.nttdata.com
> [2]
> https://www.postgresql.org/message-id/632e99eb-8090-53e6-1b1a-101601904cbd%40oss.nttdata.com
>
> > Is that because there was no ActivePortal created or the ActivePortal
> > pointed to DO block instead of PERFORM pg_sleep?
>
> ActivePortal is created but ActivePortal->queryDesc is null.

Thanks.

>
> >> > 2. When a query is running in parallel worker do we want to print that
> >> > query? It may or may not be interesting given the situation. If the
> >> > overall plan itself is faulty, output of the parallel worker query is
> >> > not useful. If the plan is fine but a given worker's leg is running
> >> > slowly it may be interesting.
> >>
> >> I think it can be useful.
> >> I'm wondering if we can add this after the first patch for this
> >> feature
> >> is committed.
> >
> > With the current patches, it will print the query from a parallel
> > backend. If that's not desirable we should prohibit that case at
> > least.
>
> Current patch prohibits printing plan if backend type is parallel worker
> as below:
>
> =# select pg_log_query_plan(pid), backend_type from pg_stat_activity
> where backend_type = 'parallel worker';
>
> pg_log_query_plan | backend_type
> -------------------+-----------------
> f | parallel worker
> f | parallel worker
> (2 rows)
>
> WARNING: PID 4618 is not a PostgreSQL client backend process
> WARNING: PID 4617 is not a PostgreSQL client backend process
>
> Is this the behavior you expect?
>

I misread then. Thanks for correcting me. We could consider plans from
parallel workers in v2 of this feature.

--
Best Wishes,
Ashutosh Bapat