public inbox for [email protected]
help / color / mirror / Atom feedFrom: torikoshia <[email protected]>
To: Ashutosh Bapat <[email protected]>
Cc: Étienne BERSAC <[email protected]>
Cc: Andres Freund <[email protected]>
Cc: [email protected]
Cc: [email protected]
Subject: Re: RFC: Logging plan of the running query
Date: Thu, 09 Nov 2023 20:26:27 +0900
Message-ID: <[email protected]> (raw)
In-Reply-To: <CAExHW5utSXjEMh6BWBPEe3Ks70T12VcGZqR8YH1owhZoROv4fw@mail.gmail.com>
References: <[email protected]>
<CAAaqYe9TPyWe9yoOm5Jz_39gSnhCAYXozc698jkyegM1x74Qjg@mail.gmail.com>
<CAAaqYe9Mse7JC78DgT97sXoB6U+E5OL3zJAYRSsgy-TPP9PXmw@mail.gmail.com>
<[email protected]>
<CAAaqYe_5p_MkBCgSYX=S7G3ZKi=2=_6bZQFzTgVYyv=1NRikpw@mail.gmail.com>
<[email protected]>
<CAAaqYe_hyWLs-ObFQfu54yA-ZOjNCd-L_Z=1TnYjYNqrLuGiXQ@mail.gmail.com>
<[email protected]>
<CAAaqYe_p-849MtsVgN9_y-YL-uFzLFMpGw38T3Omb11gw-=K1w@mail.gmail.com>
<[email protected]>
<[email protected]>
<[email protected]>
<CAExHW5ujL=mzbjxf6xtyU-Ft6LMBMEmt8H4ZSDiiZre0Fef0jg@mail.gmail.com>
<[email protected]>
<CAExHW5s+T0Ds-h85y92MsryLqup8fuAT8bovgGGaNnLt=OrQOg@mail.gmail.com>
<[email protected]>
<[email protected]>
<[email protected]>
<[email protected]>
<[email protected]>
<[email protected]>
<CAExHW5vnoyd750bpjOJr58F33tN+hROAqVqv1nYRVPwd9XtgSg@mail.gmail.com>
<CAExHW5t+xh95_LZjkUZARDbV=gS5pBJghG8x=Xnjb2psWr0R6g@mail.gmail.com>
<[email protected]>
<CAExHW5utSXjEMh6BWBPEe3Ks70T12VcGZqR8YH1owhZoROv4fw@mail.gmail.com>
On 2023-11-09 16:11, Ashutosh Bapat wrote:
> On Thu, Nov 9, 2023 at 12:03 PM torikoshia <[email protected]>
> 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
view thread (30+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected], [email protected], [email protected], [email protected]
Subject: Re: RFC: Logging plan of the running query
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox