Re: Duplicate Workers entries in some EXPLAIN plans

Hi,

On 2020-01-25 14:23:50 -0500, Tom Lane wrote:
> A side effect of this change is that per-worker JIT info is now
> printed one plan level further down: before it was printed on
> the Gather node, but now it's attached to the Gather's child,
> because that's where we print other per-worker data. I don't
> see anything particularly wrong with that, but it's another
> change from the behavior today.

Yea, I don't see any need to be bothered by that.

> It's still really unclear to me how we could exercise any of
> this behavior meaningfully in a regression test. I thought
> for a little bit about using the TAP infrastructure instead
> of a traditional-style test, but it seems like that doesn't
> buy anything except for a bias towards ignoring details instead
> of overspecifying them. Which is not much of an improvement.

Hm. I'd like to avoid needing TAP for this kind of thing, it'll just
make it much more expensive in just about all ways.

Testing JIT explain is "easy" enough I think, I've posted a patch in
another thread, which just skips over the region of the test if JIT is
not available. See e.g. 0008 in
https://www.postgresql.org/message-id/20191029000229.fkjmuld3g7f2jq7i%40alap3.anarazel.de
(that's a thread I'd love your input in btw)

It's harder for parallel query though. If parallel query were able to
reuse workers, we could "just" check at the beginning of the test if we
are able to get the workers we need, and then skip the rest of the tests
if not. But as things stand that doesn't guarantee anything.

I wonder if we could introduce a debug GUC that makes parallel worker
acquisition just retry in a loop, for a time determined by the GUC. That
obviously would be a bad idea to do in a production setup, but it could
be good enough for regression tests? There are some deadlock dangers,
but I'm not sure they really matter for the tests.

> + /* prepare per-worker general execution details */
> + if (es->workers_state && es->verbose)
> + {
> + WorkerInstrumentation *w = planstate->worker_instrument;
> +
> + for (int n = 0; n < w->num_workers; n++)
> + {
> + Instrumentation *instrument = &w->instrument[n];
> + double nloops = instrument->nloops;
> + double startup_ms;
> + double total_ms;
> + double rows;
> +
> + if (nloops <= 0)
> + continue;
> + startup_ms = 1000.0 * instrument->startup / nloops;
> + total_ms = 1000.0 * instrument->total / nloops;
> + rows = instrument->ntuples / nloops;
> +
> + ExplainOpenWorker(n, es);
> +
> + if (es->format == EXPLAIN_FORMAT_TEXT)
> + {
> + ExplainIndentText(es);
> + if (es->timing)
> + appendStringInfo(es->str,
> + "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n",
> + startup_ms, total_ms, rows, nloops);
> + else
> + appendStringInfo(es->str,
> + "actual rows=%.0f loops=%.0f\n",
> + rows, nloops);
> + }
> + else
> + {
> + if (es->timing)
> + {
> + ExplainPropertyFloat("Actual Startup Time", "ms",
> + startup_ms, 3, es);
> + ExplainPropertyFloat("Actual Total Time", "ms",
> + total_ms, 3, es);
> + }
> + ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es);
> + ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es);
> + }
> +
> + ExplainCloseWorker(n, es);
> + }
> + }

I'd personally move this into a separate function, given the patches
moves the code around already. ExplainNode() is already hard enough to
navigate...

It probably also makes sense to move everything but the nloops <= 0,
ExplainOpenWorker/ExplainCloseWorker into its own function. As far as I
can tell it now should be identical between the non-parallel case?

> +/*
> + * Begin or resume output into the set-aside group for worker N.
> + */
> +static void

Would it make sense to make these functions non-static? It seems
plausible that code for a custom node or such would want to add
its own information?

> +ExplainOpenWorker(int n, ExplainState *es)
> +{
> + ExplainWorkersState *wstate = es->workers_state;
> +
> + Assert(wstate);
> + Assert(n >= 0 && n < wstate->num_workers);
> +
> + /* Save prior output buffer pointer */
> + wstate->prev_str = es->str;
> +
> + if (!wstate->worker_inited[n])
> + {
> + /* First time through, so create the buffer for this worker */
> + initStringInfo(&wstate->worker_str[n]);
> + es->str = &wstate->worker_str[n];
> +
> + /*
> + * Push suitable initial formatting state for this worker's field
> + * group. We allow one extra logical nesting level, since this group
> + * will eventually be wrapped in an outer "Workers" group.
> + */
> + ExplainOpenSetAsideGroup("Worker", NULL, true, 2, es);
> +
> + /*
> + * In non-TEXT formats we always emit a "Worker Number" field, even if
> + * there's no other data for this worker.
> + */
> + if (es->format != EXPLAIN_FORMAT_TEXT)
> + ExplainPropertyInteger("Worker Number", NULL, n, es);
> +
> + wstate->worker_inited[n] = true;
> + }
> + else
> + {
> + /* Resuming output for a worker we've already emitted some data for */
> + es->str = &wstate->worker_str[n];
> +
> + /* Restore formatting state saved by last ExplainCloseWorker() */
> + ExplainRestoreGroup(es, 2, &wstate->worker_state_save[n]);
> + }
> +
> + /*
> + * In TEXT format, prefix the first output line for this worker with
> + * "Worker N:". Then, any additional lines should be indented one more
> + * stop than the "Worker N" line is.
> + */
> + if (es->format == EXPLAIN_FORMAT_TEXT)
> + {
> + if (es->str->len == 0)
> + {
> + ExplainIndentText(es);
> + appendStringInfo(es->str, "Worker %d: ", n);
> + }
> +
> + es->indent++;
> + }
> +}

I don't quite get the Worker %d bit. Why are we not outputting that in
the !worker_inited block?

> +/*
> + * Print per-worker info for current node, then free the ExplainWorkersState.
> + */
> +static void
> +ExplainFlushWorkersState(ExplainState *es)
> +{
> + ExplainWorkersState *wstate = es->workers_state;
> +
> + ExplainOpenGroup("Workers", "Workers", false, es);
> + for (int i = 0; i < wstate->num_workers; i++)
> + {
> + if (wstate->worker_inited[i])
> + {
> + /* This must match previous ExplainOpenSetAsideGroup call */
> + ExplainOpenGroup("Worker", NULL, true, es);
> + appendStringInfoString(es->str, wstate->worker_str[i].data);

Probably never matters, but given we do have the string length already,
we could use appendBinaryStringInfo().

> + ExplainCloseGroup("Worker", NULL, true, es);

Not related to this patch: I never got why we maintain a grouping stack
for some things, but don't do it for the group properties
themselves.

> /*
> + * Open a group of related objects, without emitting actual data.
> + *
> + * Prepare the formatting state as though we were beginning a group with
> + * the identified properties, but don't actually emit anything. Output
> + * subsequent to this call can be redirected into a separate output buffer,
> + * and then eventually appended to the main output buffer after doing a
> + * regular ExplainOpenGroup call (with the same parameters).
> + *
> + * The extra "depth" parameter is the new group's depth compared to current.
> + * It could be more than one, in case the eventual output will be enclosed
> + * in additional nesting group levels. We assume we don't need to track
> + * formatting state for those levels while preparing this group's output.
> + *
> + * There is no ExplainCloseSetAsideGroup --- in current usage, we always
> + * pop this state with ExplainSaveGroup.
> + */
> +static void
> +ExplainOpenSetAsideGroup(const char *objtype, const char *labelname,
> + bool labeled, int depth, ExplainState *es)
> +{
> + switch (es->format)
> + {
> + case EXPLAIN_FORMAT_TEXT:
> + /* nothing to do */
> + break;
> +
> + case EXPLAIN_FORMAT_XML:
> + es->indent += depth;
> + break;
> +
> + case EXPLAIN_FORMAT_JSON:
> + es->grouping_stack = lcons_int(0, es->grouping_stack);
> + es->indent += depth;
> + break;
> +
> + case EXPLAIN_FORMAT_YAML:
> + if (labelname)
> + es->grouping_stack = lcons_int(1, es->grouping_stack);
> + else
> + es->grouping_stack = lcons_int(0, es->grouping_stack);
> + es->indent += depth;
> + break;
> + }
> +}

Hm. It might be worthwhile to rename ExplainOpenSetAsideGroup and use it
from ExplainOpenGroup()? Seems we could just call it after
ExplainOpenGroup()'s switch, and remove all the indent/grouping_stack
related code from ExplainOpenGroup().

Greetings,

Andres Freund