Re: RFC: Logging plan of the running query

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.

>> > 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?

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation