Re: RFC: Logging plan of the running query - Mailing list pgsql-hackers

On 2023-11-09 16:11, Ashutosh Bapat wrote:
> On Thu, Nov 9, 2023 at 12:03 PM torikoshia <torikoshia@oss.nttdata.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