Re: Stack-based tracking of per-node WAL/buffer usage - Mailing list pgsql-hackers

> +/*
> + * General purpose instrumentation that can capture time, WAL/buffer usage and tuples
> + *
> + * Initialized through InstrAlloc, followed by one or more calls to a pair of
> + * InstrStart/InstrStop (activity is measured inbetween).
> + */
>  typedef struct Instrumentation
> +{
> +     /* Parameters set at creation: */
> +     bool            need_timer;             /* true if we need timer data */
> +     bool            need_bufusage;  /* true if we need buffer usage data */
> +     bool            need_walusage;  /* true if we need WAL usage data */
> +     /* Internal state keeping: */
> +     instr_time      starttime;              /* start time of last InstrStart */
> +     BufferUsage bufusage_start; /* buffer usage at start */
> +     WalUsage        walusage_start; /* WAL usage at start */
> +     /* Accumulated statistics: */
> +     instr_time      total;                  /* total runtime */
> +     double          ntuples;                /* total tuples counted in InstrStop */
> +     BufferUsage bufusage;           /* total buffer usage */
> +     WalUsage        walusage;               /* total WAL usage */
> +} Instrumentation;

Maybe add a comment explaining why ntuples is in here?

> ---
>  .../pg_stat_statements/pg_stat_statements.c   |   4 +-
>  src/backend/commands/explain.c                |   8 +-
>  src/backend/commands/trigger.c                |   4 +-
>  src/backend/executor/execMain.c               |  25 ++-
>  src/backend/executor/execProcnode.c           |  29 +++
>  src/backend/executor/instrument.c             | 199 ++++++++++++++----
>  src/include/executor/executor.h               |   1 +
>  src/include/executor/instrument.h             |  53 ++++-
>  8 files changed, 260 insertions(+), 63 deletions(-)
>
> diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
> index f43a33b3787..eeabd820d8e 100644
> --- a/contrib/pg_stat_statements/pg_stat_statements.c
> +++ b/contrib/pg_stat_statements/pg_stat_statements.c
> @@ -1089,8 +1089,8 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
>                                  PGSS_EXEC,
>                                  INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total),
>                                  queryDesc->estate->es_total_processed,
> -                                &queryDesc->totaltime->bufusage,
> -                                &queryDesc->totaltime->walusage,
> +                                &INSTR_GET_BUFUSAGE(queryDesc->totaltime),
> +                                &INSTR_GET_WALUSAGE(queryDesc->totaltime),

Getting a pointer to something returned by a macro is a bit ugly... Perhaps
it'd be better to just pass the &queryDesc->totaltime? But ugh, that's not
easily possible given how pgss_planner() currently tracks things :(

Maybe it's worth refactoring this a bit in a precursor patch?

>  /* ------------------------------------------------------------------------
> @@ -828,6 +829,34 @@ ExecShutdownNode_walker(PlanState *node, void *context)
>       return false;
>  }
>
> +/*
> + * ExecAccumNodeInstrumentation
> + *
> + * Accumulate instrumentation stats from all execution nodes to their respective
> + * parents (or the original parent instrumentation stack).
> + */
> +void
> +ExecAccumNodeInstrumentation(PlanState *node)
> +{
> +     (void) ExecAccumNodeInstrumentation_walker(node, NULL);
> +}

I wonder if this is too narrow a name. There might be other uses of a pass
across the node tree at that point. OTOH, it's probably better to just rename
it at that later point.

> +     if (node->instrument && node->instrument->stack.previous)
> +             InstrStackAdd(node->instrument->stack.previous, &node->instrument->stack);
> +
> +     return false;
> +}

E.g. in ExecShutdownNode_walker we use planstate_tree_walker(), but then also
have special handling for a few node types. Do we need something like that
here too?  It probably is ok, but it's worth explicitly checking and adding a
comment.

> +/*
> + * Use ResourceOwner mechanism to correctly reset pgInstrStack on abort.
> + */
> +static void ResOwnerReleaseInstrumentation(Datum res);
> +static const ResourceOwnerDesc instrumentation_resowner_desc =
> +{
> +     .name = "instrumentation",
> +     .release_phase = RESOURCE_RELEASE_BEFORE_LOCKS,
> +     .release_priority = RELEASE_PRIO_FIRST,
> +     .ReleaseResource = ResOwnerReleaseInstrumentation,
> +     .DebugPrint = NULL,                     /* default message is fine */
> +};

Is there a reason to do the release here before the lock release? And why
_FIRST?

> +     if (pgInstrStack && !StackIsParent(pgInstrStack, &instr->stack))
> +             pgInstrStack = instr->stack.previous;

Hm - this is effectively O(stack-depth^2), right?  It's probably fine, given
that we have fairly limited nesting (explain + pg_stat_statements +
auto_explain is probably the current max), but seems worth noting in a
comment?

> +     /*
> +      * Always accumulate all collected stats before the abort, even if we
> +      * already walked up the stack with an earlier resource.
> +      */
> +     if (pgInstrStack)
> +             InstrStackAdd(pgInstrStack, &instr->stack);

Why are we accumulating stats in case of errors? It's probably fine, but doing
less as part of cleanup is pre ferrable...

>  /* General purpose instrumentation handling */
>  Instrumentation *
>  InstrAlloc(int n, int instrument_options)
>  {
...
> +     if (need_buffers || need_wal)
> +             instr = MemoryContextAllocZero(CurTransactionContext, n * sizeof(Instrumentation));
> +     else
> +             instr = palloc0(n * sizeof(Instrumentation));

Is this long-lived enough? I'm e.g. wondering about utility statements that
internally starting transactions, wouldn't that cause problems with a user
like pgss tracking something like CIC?

> +void
> +InstrStackAdd(InstrStack * dst, InstrStack * add)
> +{
> +     Assert(dst != NULL);
> +     Assert(add != NULL);
> +
> +     BufferUsageAdd(&dst->bufusage, &add->bufusage);
> +     WalUsageAdd(&dst->walusage, &add->walusage);
>  }
>

Do we want to do BufferUsageAdd() etc even if we are not tracking buffer
usage? Those operations aren't cheap...

>  /* note current values during parallel executor startup */
> @@ -281,6 +386,14 @@ InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
>  void
>  InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
>  {
> +     if (pgInstrStack != NULL)
> +     {
> +             InstrStack *dst = pgInstrStack;
> +
> +             BufferUsageAdd(&dst->bufusage, bufusage);
> +             WalUsageAdd(&dst->walusage, walusage);
> +     }
> +
>       BufferUsageAdd(&pgBufferUsage, bufusage);
>       WalUsageAdd(&pgWalUsage, walusage);
>  }

Is the pgInstrStack == NULL case actually reachable?