Re: RFC: Logging plan of the running query

On 2026-08-24 16:29, Andrei Lepikhov wrote:
Thanks for the explanation.

> On 21/07/2026 17:54, torikoshia wrote:
>>
>>> Hmmm, asynchronous feature that explains an arbitrary part of the
>>> query - for
>>> example, some query inside an evaluated plpgsql function ... I think
>>> it is
>>> expected by design.
>>
>> Even when execution moves to an outer or deeper QueryDesc in this way,
>> the LogQueryPlanPending flag remains set, so the plan is logged. [1]
>>
>> The plan is not logged when there is no subsequent opportunity to call
>> ExecProcNode(), including in any outer or deeper QueryDesc, as in the
>> example using PREPARE that you showed in your previous message.
>>
>> My concern is whether, without the pending flag, it would be
>> appropriate to log the plan of a different query subsequently
>> executed by the same backend.
>>
>> For example, suppose a user calls pg_log_query_plan() expecting
>> the plan of query A to be logged, but there is no opportunity
>> to do so. If query B is then executed by the same backend one
>> hour later, the plan of query B would be logged at that point.
>> This does not seem like behavior that users would expect.
>> What do you think?
>
> Hmm, maybe I wasn't clear enough. Let me explain. This feature is
> asynchronous
> by design. Calling it, you never know if the signal will be processed
> in the
> exact query you saw a moment ago in pg_stat_activity. Moreover, it may
> be an
> internal query inside of a massive query - it can be hard for a user to
> match
> this call and the logged query. Just for example:
>
> CREATE OR REPLACE FUNCTION heavy_nested_probe() RETURNS bigint
> LANGUAGE plpgsql AS $$
> DECLARE
> result bigint;
> BEGIN
> SELECT count(*) INTO result
> FROM generate_series(1, 150000000) g(i) WHERE i % 7 = 0; RETURN
> result;
> END; $$; SQL
>
> SELECT heavy_nested_probe();
>
> Calling SELECT pg_log_query_plan() to the backend, executing such a
> query, you
> will probably see 'SELECT heavy_nested_probe ', but the log file
> contains:
>
> LOG: query and its plan for queryid 0 running on backend with PID
> 15805 are:
> Query Text: SELECT count(*) FROM generate_series(1, 150000000) g(i)
> WHERE i % 7 = 0
> Aggregate (cost=2251875.00..2251875.01 rows=1 width=8)
> -> Function Scan on generate_series g
> (cost=0.00..2250000.00 rows=750000 width=0)
> Filter: ((i % 7) = 0)
>
> So, my point is Postgres shouldn't pretend that it provides any
> guarantees: this
> function is a direct target for DBA's automation, and it might cause
> questions.

Perhaps something in the discussion gave that impression, but the patch
is not intended to guarantee that the logged plan corresponds to the
query that the caller observed in pg_stat_activity.

The documentation notes that processing is asynchronous, that logging
may be delayed or may not happen at all:

---
The plan is logged when the target backend next reaches a
point where the running plan can be inspected. If the backend
is spending a long time in work that does not reach such a
point, the log output can be delayed until that work
completes. If the query finishes before such a point is
reached, no plan may be logged.
---

It also notes that, when nested queries are being executed, the
innermost query may be logged:

---
If the target backend is executing a nested query when it
processes the request, only the plan of the innermost
executing query is logged.
---

Clearing LogQueryPlanPending at the end of ExecutorRun() is not intended
to provide a stronger guarantee about which query is logged. Its purpose
is to bound the lifetime of an unfulfilled request, so that it does not
remain pending indefinitely and unexpectedly log the plan of an
unrelated statement executed much later in the same session.

> Just make it an asynchronous function and provide users with a way to
> know
> whether it has already been logged and to match the call to the
> specific log record.

I'm still not sure if it's reasonable to add a dedicated
request tracking mechanism for pg_log_query_plan().

For example, pg_log_backend_memory_contexts() is a similar asynchronous
diagnostic function. It requests another process to write information to
the server log, but it does not provide a separate way to determine
whether the request has already been processed or to associate an
individual call with a particular log record. It also cannot guarantee
that the logged memory contexts represent the exact state that the
caller observed before sending the request.

More generally, diagnostic tools that inspect a changing execution
state are often used as sampling tools. For example, when investigating
a process with a stack-tracing tool such as pstack, it is common to take
several stack traces at once.

I view pg_log_query_plan() similarly.
A DBA may issue the request several times to obtain useful diagnostic
samples, rather than expecting one call to identify the exact
state observed earlier in pg_stat_activity.

What do you think?

Thanks,

--
Atsushi Torikoshi
Seconded from NTT DATA CORPORATION to SRA OSS K.K.