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.
