Re: RFC: Logging plan of the running query

On 2026-06-08 15:08, Lukas Fittl wrote:

Thanks for your review and update again.

> Hi,
>
> On Mon, Mar 16, 2026 at 8:14 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> Rebased the patch.
>
> I was reminded about this patch at PG DATA in Chicago last week, and
> figured I'd see if I can contribute a review / help move this forward
> in PG20.
>
> First of all, find attached a v54 that is rebased over changes late in
> the PG19 cycle, with other minimal fixes:
>
> - Add a missing call to explain_per_plan_hook in ExplainStringAssemble
> (this hook was newly added after your last patch version)
> - The TAP test number (11) was overlapping with an existing test
> (011_lock_stats) that was recently added, renumbered to
> 014_pg_log_query_plan.pl
> - Add missing reference for the TAP test in Meson builds
> - Adjust auto_explain.c to not include "dynamic_explain.h" (its not
> needed, ExplainStringAssemble is defined in explain.h which is already
> included)
> - pgindent run to fix minor whitespace issues in dynamic_explain.c

Agreed on those changes.

> I've also read through the other thread re: progressive explain, and
> it seems like this infrastructure here to log the current plan
> (without ANALYZE) would be required in any case (and I think the
> overall approach makes sense), and then separately we can solve the
> progressive explain's parallel worker and other design issues around
> execution statistics.
>
> In terms of code review:
>
>> diff --git a/src/backend/access/transam/xact.c
>> b/src/backend/access/transam/xact.c
>> index aafc53e0164..09e51b3d75a 100644
>> --- a/src/backend/access/transam/xact.c
>> +++ b/src/backend/access/transam/xact.c
>> @@ -37,6 +37,7 @@
>> #include "catalog/pg_enum.h"
>> #include "catalog/storage.h"
>> #include "commands/async.h"
>> +#include "commands/dynamic_explain.h"
>> #include "commands/tablecmds.h"
>> #include "commands/trigger.h"
>> #include "common/pg_prng.h"
>> @@ -217,6 +218,7 @@ typedef struct TransactionStateData
>> bool parallelChildXact; /* is any parent transaction
>> parallel? */
>> bool chain; /* start a new block after this one
>> */
>> bool topXidLogged; /* for a subxact: is top-level XID
>> logged? */
>> + QueryDesc *queryDesc; /* my current QueryDesc */
>> struct TransactionStateData *parent; /* back link to parent */
>> } TransactionStateData;
>
> Somehow putting the current QueryDesc into TransactionStateData seemed
> a bit odd to me, and I briefly experimented with putting this into the
> active portal instead - but that doesn't work with subtransactions
> that don't have their own portal, which presumably is how you landed
> on this design. So I think this makes sense as-is, given those
> challenges.
>
>> @@ -2953,6 +2977,9 @@ AbortTransaction(void)
>> /* Reset snapshot export state. */
>> SnapBuildResetExportedSnapshotState();
>>
>> + /* Reset current query plan state used for logging. */
>> + SetCurrentQueryDesc(NULL);
>> +
>> /*
>> * If this xact has started any unfinished parallel operation,
>> clean up
>> * its workers and exit parallel mode. Don't warn about leaked
>> resources.
>> @@ -5352,6 +5379,13 @@ AbortSubTransaction(void)
>> /* Reset logical streaming state. */
>> ResetLogicalStreamingState();
>>
>> + /*
>> + * Reset current query plan state used for logging. Note that
>> even after
>> + * this reset, it's still possible to obtain the parent
>> transaction's
>> + * query plans, since they are preserved in
>> standard_ExecutorRun().
>> + */
>> + SetCurrentQueryDesc(NULL);
>> +
>> /*
>> * No need for SnapBuildResetExportedSnapshotState() here,
>> snapshot
>> * exports are not supported in subtransactions.
>
> It seems better to me if we avoided overly specific code comments in
> xact.c that talk about plan logging behavior, i.e. look at this more
> as a general purpose "what's the current queryDesc for the current
> transaction" facility.

Removed specific comments about plan logging.

>> diff --git a/src/backend/executor/execProcnode.c
>> b/src/backend/executor/execProcnode.c
>> index 7e40b852517..96cb22daf80 100644
>> --- a/src/backend/executor/execProcnode.c
>> +++ b/src/backend/executor/execProcnode.c
>> @@ -441,27 +443,43 @@ ExecSetExecProcNode(PlanState *node,
>> ExecProcNodeMtd function)
>> ...
>> static TupleTableSlot *
>> ExecProcNodeFirst(PlanState *node)
>> {
>> ...
>> + if (LogQueryPlanPending)
>> + LogQueryPlan();
>> +
>> /*
>> * If instrumentation is required, change the wrapper to one that
>> just
>> * does instrumentation. Otherwise we can dispense with all
>> wrappers and
>> * have ExecProcNode() directly call the relevant function from
>> now on.
>> */
>> - if (node->instrument)
>> + else if (node->instrument)
>> node->ExecProcNode = ExecProcNodeInstr;
>> else
>> node->ExecProcNode = node->ExecProcNodeReal;
>
> I'm not sure if this was discussed earlier already, but I find the
> flow here a bit hard to follow in regards to how we execute the actual
> node function again.
>
> Specifically, since this uses "else if" we don't touch ExecProcNode
> when LogQueryPlanPending = true, and since node->ExecProcNode still
> points to ExecProcNodeFirst, the function basically calls itself. On
> the second go around we assume that LogQueryPlanPending is no longer
> set, so we get back to the intended ExecProcNode *if*
> LogQueryPlanPending was set to false (which it is in LogQueryPlan, but
> that's not easy to see from just that function).
>
> Why not do it like this:
>
> if (LogQueryPlanPending)
> LogQueryPlan();
>
> /* Unmodified existing code */
> if (node->instrument)
> node->ExecProcNode = ExecProcNodeInstr;
> else
> node->ExecProcNode = node->ExecProcNodeReal;
>

Make sense. Modified it.

I also fixed some typos in the attached patch.

Thanks,

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