Re: RFC: Logging plan of the running query

On Sat, Sep 20, 2025 at 2:04 AM Rafael Thofehrn Castro
<rafaelthca@gmail.com> wrote:
> apologies for not replying earlier. Thanks torikoshia for having
> reviewed the related patch I sent that includes instrumentation.
> It makes total sense to focus on this one first.

Thank you as well for agreeing on the direction for how to proceed!

> Been thinking about the current strategy of having to iterate through
> the execution tree to add the custom ExecProcNode to avoid logging
> the plan in CHECK_FOR_INTERRUPTS(). I see you folks are still
> discussing all the nuances in the recursive tree traversal function.
>
> Taking a step back and proposing a different approach, have we thought
> about logging the query plan in the regions of the code related to the
> query executor, NEXT to CHECK_FOR_INTERRUPTS calls instead of IN
> that function?

As a related discussion, there was an idea of splitting
CHECK_FOR_INTERRUPTS() into two variants: one for cases where it’s
safe to perform operations like plan logging, and one where it isn’t:

https://www.postgresql.org/message-id/CAAaqYe-gMkdL%3DM4v47%3DH0F3%2B-zi2qL9zFqAv3QsizkRjFiQR0w%40mail.gmail.com

However, as I mentioned later in this thread, there were some issues,
so the current discussion has focused on the node-wrapping approach
instead.

> For example, in this part of executor/nodeHashjoin.c:
>
> for (;;)
> {
>   /*
>    * It's possible to iterate this loop many times before returning a
>    * tuple, in some pathological cases such as needing to move much of
>    * the current batch to a later batch.  So let's check for interrupts
>    * each time through.
>    */
>   CHECK_FOR_INTERRUPTS();
>
> We replace CHECK_FOR_INTERRUPTS() for a new function that does
> query plan logging logic + CHECK_FOR_INTERRUPTS().
>
> Would that be considered a safe operation given that we would always be
> in the query execution context? The current ExecProcNode wrapper strategy
> logs the query plan in ExecProcNodeFirst(). That function will then call
> the real ExecProcNode, which points to one of the functions that contain
> the CHECK_FOR_INTERRUPTS in the first place. I don't see much difference
> in terms of logging safety between the two approaches, but maybe there
> is :)

IIUC, the differences between the two approaches are:

(1) Timing of plan output
Current patch: The plan is logged the first time each node’s
ExecProcNode() begins execution.
Your idea: The plan is logged at each “NEXT to CHECK_FOR_INTERRUPTS()”
point inside the node.

(2) Number of checks for whether plan output is needed
Current patch: Once after logging plan is requested
Your idea: Every time execution reaches a “NEXT to
CHECK_FOR_INTERRUPTS()” point inside the node.

At least Robert and I believe that the first execution of each node’s
ExecProcNode() represents a sufficiently consistent state for plan
output, as noted in the patch comments:

  +   /*
  +    * If we have been asked to print the query plan, do that now. We dare not
  +    * try to do this directly from CHECK_FOR_INTERRUPTS() because we don't
  +    * really know what the executor state is at that point, but we assume
  +    * that when entering a node the state will be sufficiently consistent
  +    * that trying to print the plan makes sense.
  +    */
  +   if (LogQueryPlanPending)
  +       LogQueryPlan();

Investigating consistency at each of those points would not be easy,
and given the variety of node types, while not impossible, it would be
very difficult.

As for point (2), it’s not directly about safety, but the idea could
introduce performance overhead due to the repeated checks.

Regards,
Atsushi Torikoshi