Duplicate Workers entries in some EXPLAIN plans

Hi,

On 2019-10-22 11:58:35 -0700, Maciek Sakrejda wrote:

I originally reported this in pgsql-bugs [0], but there wasn't much
feedback there, so moving the discussion here. When using JSON, YAML, or
XML-format EXPLAIN on a plan that uses a parallelized sort, the Sort nodes
list two different entries for "Workers", one for the sort-related info,
and one for general worker info. This is what this looks like in JSON (some
details elided):

{
"Node Type": "Sort",
...
"Workers": [
{
"Worker Number": 0,
"Sort Method": "external merge",
"Sort Space Used": 20128,
"Sort Space Type": "Disk"
},
{
"Worker Number": 1,
"Sort Method": "external merge",
"Sort Space Used": 20128,
"Sort Space Type": "Disk"
}
],
...
"Workers": [
{

This is technically valid JSON, but it's extremely difficult to work with,
since default JSON parsing in Ruby, node, Python, Go, and even Postgres'
own jsonb only keep the latest key

It's also quite confusing.

As Tom Lane pointed out in my pgsql-bugs thread, this has been
reported before [1] and in that earlier thread, Andrew Dunstan suggested
that perhaps the simplest solution is to just rename the sort-related
Workers node. Thoughts?

Yea, I think we should fix this. The current output basically makes no
sense.

Tom expressed some concerns about a breaking change here,
though I think the current behavior means vanishingly few users are parsing
this data correctly.

Well, in a lot of the cases there's no parallel output for the sort, and
in other cases BUFFERS is not specified. In either case the 'duplicate
key' problem won't exist then.

While Tom said:

On 2019-10-16 09:16:56 +0200, Tom Lane wrote:

I think the text-mode output is intentional, but the other formats
need more work.

Sort Method: external merge Disk: 4920kB
Worker 0: Sort Method: external merge Disk: 5880kB
Worker 1: Sort Method: external merge Disk: 5920kB
Buffers: shared hit=682 read=10188, temp read=1415 written=2101
Worker 0: actual time=130.058..130.324 rows=1324 loops=1
Buffers: shared hit=337 read=3489, temp read=505 written=739
Worker 1: actual time=130.273..130.512 rows=1297 loops=1
Buffers: shared hit=345 read=3507, temp read=505 written=744

I don't think this is close to being good enough to be worth
preserving. I think it's worth avoiding unnecessary breakage of explain
output, but we also shouldn't endlessly carry forward confusing output,
just because of that.

It clearly seems like it'd be better if this instead were

Sort Method: external merge Disk: 4920kB
Buffers: shared hit=682 read=10188, temp read=1415 written=2101
Worker 0: actual time=130.058..130.324 rows=1324 loops=1
Sort Method: external merge Disk: 5880kB
Buffers: shared hit=337 read=3489, temp read=505 written=739
Worker 1: actual time=130.273..130.512 rows=1297 loops=1
Buffers: shared hit=345 read=3507, temp read=505 written=744
Sort Method: external merge Disk: 5920kB

I think the way this information was added in bf11e7ee2e36 and
33001fd7a707, contrasting to the output added in b287df70e408, is just
not right. If we add similar instrumentation reporting to more nodes,
we'll end up with duplicated information all over. Additionally the
per-worker part of show_sort_info() basically just duplicated the rest
of the function. I then also did something similar (although luckily
with a different key...), with the ExplainPrintJIT() call for Gather
nodes.

Unfortunately I think the fix isn't all that trivial, due to the way we
output the per-worker information at the end of ExplainNode(), by just
dumping things into a string. It seems to me that a step in the right
direction would be for ExplainNode() to create
planstate->worker_instrument StringInfos, which can be handed to
routines like show_sort_info(), which would print the per-node
information into that, rather than directly dumping into
es->output. Most of the current "Show worker detail" would be done
earlier in ExplainNode(), at the place where we current display the
"actual rows" bit.

ISTM that should include removing the duplication fo the the contents of
show_sort_info(), and probably also for the Gather, GatherMerge blocks
(I've apparently skipped adding the JIT information to the latter, not
sure if we ought to fix that in the stable branches).

Any chance you want to take a stab at that?

I don't think we'll fix it soon, but damn, all this string appending
around just isn't a great way to reliably build nested data formats.

Greetings,

Andres Freund

On Thu, Oct 24, 2019 at 6:48 PM Andres Freund <andres@anarazel.de> wrote:

Unfortunately I think the fix isn't all that trivial, due to the way we
output the per-worker information at the end of ExplainNode(), by just
dumping things into a string. It seems to me that a step in the right
direction would be for ExplainNode() to create
planstate->worker_instrument StringInfos, which can be handed to
routines like show_sort_info(), which would print the per-node
information into that, rather than directly dumping into
es->output. Most of the current "Show worker detail" would be done
earlier in ExplainNode(), at the place where we current display the
"actual rows" bit.

ISTM that should include removing the duplication fo the the contents of
show_sort_info(), and probably also for the Gather, GatherMerge blocks
(I've apparently skipped adding the JIT information to the latter, not
sure if we ought to fix that in the stable branches).

Any chance you want to take a stab at that?

It took me a while, but I did take a stab at it (thanks for your
off-list help). Attached is my patch that changes the structured
formats to merge sort worker output in with costs/timing/buffers
worker output. I have not touched any other worker output yet, since
it's not under a Workers group as far as I can tell (so it does not
exhibit the problem I originally reported). I can try to make further
changes here if the approach is deemed sound. I also have not touched
text output; above you had proposed

Sort Method: external merge Disk: 4920kB
Buffers: shared hit=682 read=10188, temp read=1415 written=2101
Worker 0: actual time=130.058..130.324 rows=1324 loops=1
Sort Method: external merge Disk: 5880kB
Buffers: shared hit=337 read=3489, temp read=505 written=739
Worker 1: actual time=130.273..130.512 rows=1297 loops=1
Buffers: shared hit=345 read=3507, temp read=505 written=744
Sort Method: external merge Disk: 5920kB

which makes sense to me, but I'd like to confirm this is the approach
we want before I add it to the patch.

This is my first C in close to a decade (and I was never much of a C
programmer to begin with), so please be gentle.

As Andres suggested off-list, I also changed the worker output to
order fields that also occur in the parent node in the same way as the
parent node.

I've also added a test for the patch, and because this is really an
EXPLAIN issue rather than a query feature issue, I added a
src/test/regress/sql/explain.sql for the test. I added a couple of
utility functions for munging json-formatted EXPLAIN plans into
something we can repeatably verify in regression tests (the functions
use json rather than jsonb to preserve field order). I have not added
this for YAML or XML (even though they should behave the same way),
since I'm not familiar with the the functions to manipulate those data
types in a similar way (if they exist). My hunch is due to the
similarity of structured formats, just testing JSON is enough, but I
can expand/adjust tests as necessary.

I wanted to follow up on this patch since I received no feedback. What
should my next steps be (besides rebasing, though I want to confirm there's
interest before I do that)?

On Fri, Dec 27, 2019 at 12:31 AM Maciek Sakrejda <m.sakrejda@gmail.com> wrote:

I wanted to follow up on this patch since I received no feedback. What should my next steps be (besides rebasing, though I want to confirm there's interest before I do that)?

Given Andres' answer I'd say that there's interest in this patch. You
should register this patch in the next commitfest
(https://commitfest.postgresql.org/26/) to make sure that it's not
forgotten, which unfortunately is probably what happened here .

Done! Thanks!

The following review has been posted through the commitfest application:
make installcheck-world: not tested
Implements feature: not tested
Spec compliant: not tested
Documentation: not tested

This is a high level review only. However, seeing that there is a conflict and does not merge cleanly after commit <b925a00f4ef>, I return to Author.

To be fair the resolution seems quite straight forward and I took the liberty of applying the necessary changes to include the new element of ExplainState introduced in the above commit, namely hide_workers. However since the author might have a different idea on how to incorporate this change I leave it up to him.

Another very high level comment is the introduction of a new test file, namely explain. Seeing `explain.sql` in the tests suits, personally and very opinion based, I would have expected the whole spectrum of the explain properties to be tested. However only a slight fraction of the functionality is tested. Since this is a bit more of a personal opinion, I don't expect any changes unless the author happens to agree.

Other than these minor nitpick, the code seems clear, concise and does what it says on the box. It follows the comments in the discussion thread(s) and solves a real issue.

Please have a look on how commit <b925a00f4ef> affects this patch and rebase.

The new status of this patch is: Waiting on Author

Thanks for the review! I looked at <b925a00f4ef> and rebased the patch
on current master, ac5bdf6.

I introduced a new test file because this bug is specifically about
EXPLAIN output (as opposed to query execution or planning
functionality), and it didn't seem like a test would fit in any of the
other files. I focused on testing just the behavior around this
specific bug (and fix). I think eventually we should probably test
other more fundamental EXPLAIN features (and I'm happy to contribute
to that) in that file, but that seems outside of the scope of this
patch.

Any thoughts on what we should do with text mode output (which is
untouched right now)? The output Andres proposed above makes sense to
me, but I'd like to get more input.

The following review has been posted through the commitfest application:
make installcheck-world: tested, failed
Implements feature: not tested
Spec compliant: not tested
Documentation: not tested

The current version of the patch (v2) applies cleanly and does what it says on the box.

Any thoughts on what we should do with text mode output (which is

untouched right now)? The output Andres proposed above makes sense to
me, but I'd like to get more input.

Nothing to add beyond what is stated in the thread.

Sort Method: external merge Disk: 4920kB
Buffers: shared hit=682 read=10188, temp read=1415 written=2101
Worker 0: actual time=130.058..130.324 rows=1324 loops=1
Sort Method: external merge Disk: 5880kB
Buffers: shared hit=337 read=3489, temp read=505 written=739
Worker 1: actual time=130.273..130.512 rows=1297 loops=1
Buffers: shared hit=345 read=3507, temp read=505 written=744
Sort Method: external merge Disk: 5920kB

This proposal seems like a fitting approach. Awaiting for v3 which
will include the text version. May I suggest a format yaml test case?
Just to make certain that no regressions occur in the future.

Thanks,

Sounds good, I'll try that format. Any idea how to test YAML? With the
JSON format, I was able to rely on Postgres' own JSON-manipulating
functions to strip or canonicalize fields that can vary across
executions--I can't really do that with YAML. Or should I run EXPLAIN
with COSTS OFF, TIMING OFF, SUMMARY OFF and assume that for simple
queries the BUFFERS output (and other fields I can't turn off like
Sort Space Used) *is* going to be stable?

Sounds good, I'll try that format. Any idea how to test YAML? With the
JSON format, I was able to rely on Postgres' own JSON-manipulating
functions to strip or canonicalize fields that can vary across
executions--I can't really do that with YAML.

Yes, this approach was clear in the patch and works great with Json. Also
you are correct, this can not be done with YAML. I spend a bit of time to
look around and I could not find any tests really on yaml format.

Or should I run EXPLAIN
with COSTS OFF, TIMING OFF, SUMMARY OFF and assume that for simple
queries the BUFFERS output (and other fields I can't turn off like
Sort Space Used) *is* going to be stable?

I have to admit with the current diff tool used in pg_regress, this is not possible.
I am pretty certain that it *is not* going to be stable. Not for long anyways.
I withdraw my suggestion for YAML and currently awaiting for TEXT format only.

TEXT format was tricky due to its inconsistencies, but I think I have
something working reasonably well. I added a simple test for TEXT
format output as well, using a similar approach as the JSON format
test, and liberally regexp_replacing away any volatile output. I
suppose in theory we could do this for YAML, too, but I think it's
gross enough not to be worth it, especially given the high similarity
of all the structured outputs.

The following review has been posted through the commitfest application:
make installcheck-world: not tested
Implements feature: not tested
Spec compliant: not tested
Documentation: not tested

TEXT format was tricky due to its inconsistencies, but I think I have
something working reasonably well. I added a simple test for TEXT
format output as well, using a similar approach as the JSON format

Great!

test, and liberally regexp_replacing away any volatile output. I
suppose in theory we could do this for YAML, too, but I think it's
gross enough not to be worth it, especially given the high similarity
of all the structured outputs.

Agreed, what is in the patch suffices. Overall great work, a couple of
minor nitpicks if you allow me.

+   /* Prepare per-worker output */
+   if (es->analyze && planstate->worker_instrument) {

Style, parenthesis on its own line.

+       int num_workers = planstate->worker_instrument->num_workers;
+       int n;
+       worker_strs = (StringInfo *) palloc0(num_workers * sizeof(StringInfo));
+       for (n = 0; n < num_workers; n++) {

I think C99 would be better here. Also no parenthesis needed.

+           worker_strs[n] = makeStringInfo();
+       }
+   }

@@ -1357,6 +1369,58 @@ ExplainNode(PlanState *planstate, List *ancestors,
ExplainPropertyBool("Parallel Aware", plan->parallel_aware, es);
}

+   /* Prepare worker general execution details */
+   if (es->analyze && es->verbose && planstate->worker_instrument)
+   {
+       WorkerInstrumentation *w = planstate->worker_instrument;
+       int         n;
+
+       for (n = 0; n < w->num_workers; ++n)

I think C99 would be better here.

+       {
+           Instrumentation *instrument = &w->instrument[n];
+           double      nloops = instrument->nloops;

-               appendStringInfoSpaces(es->str, es->indent * 2);
-               if (n > 0 || !es->hide_workers)
-                   appendStringInfo(es->str, "Worker %d:  ", n);
+               if (indent)
+               {
+                   appendStringInfoSpaces(es->str, es->indent * 2);
+               }

Style: No parenthesis needed

-       if (opened_group)
-           ExplainCloseGroup("Workers", "Workers", false, es);
+   /* Show worker detail */
+   if (planstate->worker_instrument) {
+       ExplainFlushWorkers(worker_strs, planstate->worker_instrument->num_workers, es);
    }

Style: No parenthesis needed

+    * just indent once, to add worker info on the next worker line.
+    */
+   if (es->str == es->root_str)
+   {
+       es->indent += es->format == EXPLAIN_FORMAT_TEXT ? 1 : 2;
+   }
+

Style: No parenthesis needed

+   ExplainCloseGroup("Workers", "Workers", false, es);
+   // do we have any other cleanup to do?

This comment does not really explain anything. Either remove
or rephrase. Also C style comments.

+ es->print_workers = false;
+}

int indent; /* current indentation level */
List *grouping_stack; /* format-specific grouping state */
+ bool print_workers; /* whether current node has worker metadata */

Hmm.. commit <b925a00f4ef> introduced `hide_workers` in the struct. Having both
names in the struct so far apart even seems a bit confusing and sloppy. Do you
think it would be possible to combine or rename?

+extern void ExplainOpenWorker(StringInfo worker_str, ExplainState *es);
+extern void ExplainCloseWorker(ExplainState *es);
+extern void ExplainFlushWorkers(StringInfo *worker_strs, int num_workers, ExplainState *es);

No need to expose those, is there? I feel there should be static.

Awaiting for answer or resolution of these comments to change the status.

//Georgios

Thanks! I'll fix the brace issues. Re: the other items:

+       int num_workers = planstate->worker_instrument->num_workers;
+       int n;
+       worker_strs = (StringInfo *) palloc0(num_workers * sizeof(StringInfo));
+       for (n = 0; n < num_workers; n++) {

I think C99 would be better here. Also no parenthesis needed.

Pardon my C illiteracy, but what am I doing that's not valid C99 here?

+   /* Prepare worker general execution details */
+   if (es->analyze && es->verbose && planstate->worker_instrument)
+   {
+       WorkerInstrumentation *w = planstate->worker_instrument;
+       int         n;
+
+       for (n = 0; n < w->num_workers; ++n)

I think C99 would be better here.

And here (if it's not the same problem)?

+   ExplainCloseGroup("Workers", "Workers", false, es);
+   // do we have any other cleanup to do?

This comment does not really explain anything. Either remove
or rephrase. Also C style comments.

Good catch, thanks--I had put this in to remind myself (and reviewers)
about cleanup, but I don't think there's anything else to do, so I'll
just drop it.

int indent; /* current indentation level */
List *grouping_stack; /* format-specific grouping state */
+ bool print_workers; /* whether current node has worker metadata */

Hmm.. commit <b925a00f4ef> introduced `hide_workers` in the struct. Having both
names in the struct so far apart even seems a bit confusing and sloppy. Do you
think it would be possible to combine or rename?

I noticed that. I was thinking about combining them, but
"hide_workers" seems to be about "pretend there is no worker output
even if there is" and "print_workers" is "keep track of whether or not
there is worker output to print". Maybe I'll rename to
"has_worker_output"?

+extern void ExplainOpenWorker(StringInfo worker_str, ExplainState *es);
+extern void ExplainCloseWorker(ExplainState *es);
+extern void ExplainFlushWorkers(StringInfo *worker_strs, int num_workers, ExplainState *es);

No need to expose those, is there? I feel there should be static.

Good call, I'll update.

+       int num_workers = planstate->worker_instrument->num_workers;
+       int n;
+       worker_strs = (StringInfo *) palloc0(num_workers * sizeof(StringInfo));
+       for (n = 0; n < num_workers; n++) {

I think C99 would be better here. Also no parenthesis needed.

Pardon my C illiteracy, but what am I doing that's not valid C99 here?

My bad, I should have been more clear. I meant that it is preferable to use
the C99 standard which calls for declaring variables in the scope that you
need them. In this case, 'n' is needed only in the for loop, so something like

for (int n = 0; n < num_workers; n++)

is preferable. To be clear, your code was perfectly valid. It was only the
style I was referring to.

+ for (n = 0; n < w->num_workers; ++n)

I think C99 would be better here.

And here (if it's not the same problem)?

Exactly the same as above.

int indent; /* current indentation level */
List *grouping_stack; /* format-specific grouping state */
+ bool print_workers; /* whether current node has worker metadata */

Hmm.. commit <b925a00f4ef> introduced `hide_workers` in the struct. Having both
names in the struct so far apart even seems a bit confusing and sloppy. Do you
think it would be possible to combine or rename?

I noticed that. I was thinking about combining them, but
"hide_workers" seems to be about "pretend there is no worker output
even if there is" and "print_workers" is "keep track of whether or not
there is worker output to print". Maybe I'll rename to
"has_worker_output"?

The rename sounds a bit better in my humble opinion. Thanks.

On Wed, Jan 22, 2020 at 9:37 AM Georgios Kokolatos <gkokolatos@pm.me> wrote:

My bad, I should have been more clear. I meant that it is preferable to use
the C99 standard which calls for declaring variables in the scope that you
need them.

Ah, I see. I think I got that from ExplainPrintSettings. I've
corrected my usage--thanks for pointing it out. I appreciate the
effort to maintain a consistent style.

int indent; /* current indentation level */
List *grouping_stack; /* format-specific grouping state */
+ bool print_workers; /* whether current node has worker metadata */

Hmm.. commit <b925a00f4ef> introduced `hide_workers` in the struct. Having both
names in the struct so far apart even seems a bit confusing and sloppy. Do you
think it would be possible to combine or rename?

I noticed that. I was thinking about combining them, but
"hide_workers" seems to be about "pretend there is no worker output
even if there is" and "print_workers" is "keep track of whether or not
there is worker output to print". Maybe I'll rename to
"has_worker_output"?

The rename sounds a bit better in my humble opinion. Thanks.

Also, reviewing my code again, I noticed that when I moved the general
worker output earlier, I missed part of the merge conflict: I had
replaced

- /* Show worker detail */
- if (es->analyze && es->verbose && !es->hide_workers &&
- planstate->worker_instrument)

with

+       /* Prepare worker general execution details */
+       if (es->analyze && es->verbose && planstate->worker_instrument)

which ignores the es->hide_workers flag (it did not fail the tests,
but the intent is pretty clear). I've corrected this in the current
patch.

I also noticed that we can now handle worker buffer output more
consistently across TEXT and structured formats, so I made that small
change too:

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 140d0be426..b23b015594 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1401,8 +1401,6 @@ ExplainNode(PlanState *planstate, List *ancestors,
                                        appendStringInfo(es->str,

"actual rows=%.0f loops=%.0f\n",

  rows, nloops);
-                               if (es->buffers)
-                                       show_buffer_usage(es,
&instrument->bufusage);
                        }
                        else
                        {
@@ -1951,7 +1949,7 @@ ExplainNode(PlanState *planstate, List *ancestors,

        /* Prepare worker buffer usage */
        if (es->buffers && es->analyze && es->verbose && !es->hide_workers
-               && planstate->worker_instrument && es->format !=
EXPLAIN_FORMAT_TEXT)
+               && planstate->worker_instrument)
        {
                WorkerInstrumentation *w = planstate->worker_instrument;
                int                     n;
diff --git a/src/test/regress/expected/explain.out
b/src/test/regress/expected/explain.out
index 8034a4e0db..a4eed3067f 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -103,8 +103,8 @@ $$, 'verbose', 'analyze', 'buffers', 'timing off',
'costs off', 'summary off'),
          Sort Key: (ROW("*VALUES*".column1))                      +
          Buffers: shared hit=114                                  +
          Worker 0: actual rows=2 loops=1                          +
-           Buffers: shared hit=114                                +
            Sort Method: xxx                                       +
+           Buffers: shared hit=114                                +
          ->  Values Scan on "*VALUES*" (actual rows=2 loops=1)    +
                Output: "*VALUES*".column1, ROW("*VALUES*".column1)+
                Worker 0: actual rows=2 loops=1                    +

I think the "producing plan output for a worker" process is easier to
reason about now, and while it changes TEXT format worker output
order, the other changes in this patch are more drastic so this
probably does not matter.

I've also addressed the other feedback above, and reworded a couple of
comments slightly.

The following review has been posted through the commitfest application:
make installcheck-world: not tested
Implements feature: not tested
Spec compliant: not tested
Documentation: not tested

Ah, I see. I think I got that from ExplainPrintSettings. I've
corrected my usage--thanks for pointing it out. I appreciate the
effort to maintain a consistent style.

Thanks, I am just following the reviewing guide to be honest.

Also, reviewing my code again, I noticed that when I moved the general
worker output earlier, I missed part of the merge conflict:

Right. I thought that was intentional.

which ignores the es->hide_workers flag (it did not fail the tests,
but the intent is pretty clear). I've corrected this in the current
patch.

Noted and appreciated.

I also noticed that we can now handle worker buffer output more
consistently across TEXT and structured formats, so I made that small
change too:

Looks good.

I think the "producing plan output for a worker" process is easier to
reason about now, and while it changes TEXT format worker output
order, the other changes in this patch are more drastic so this
probably does not matter.

I've also addressed the other feedback above, and reworded a couple of
comments slightly.

Thanks for the above. Looks clean, does what it says in the tin and solves a
problem that needs solving. All relevant installcheck-world pass. As far as I
am concerned, I think it is ready to be sent to a committer. Updating the status
accordingly.

The new status of this patch is: Ready for Committer

Great, thank you. I noticed in the CF patch tester app, the build
fails on Windows [1]https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.76313. Investigating, I realized I had failed to fully
strip volatile EXPLAIN info (namely buffers) in TEXT mode due to a
bad regexp_replace. I've fixed this in the attached patch (which I
also rebased against current master again).

[1]: https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.76313

Maciek Sakrejda <m.sakrejda@gmail.com> writes:

Great, thank you. I noticed in the CF patch tester app, the build
fails on Windows [1]. Investigating, I realized I had failed to fully
strip volatile EXPLAIN info (namely buffers) in TEXT mode due to a
bad regexp_replace.

You haven't gone nearly far enough in that direction. The proposed
output still relies on the assumption that the session will always
get as many workers as it asks for, which it will not. For previous
bitter experience in this department, see for instance commits 4ea03f3f4
and 13e8b2ee8.

TBH I am not sure that the proposed regression tests for this change
can be committed at all. Which is a bit of a problem perhaps, but
then again we don't have terribly good coverage for the existing code
either, for the same reason.

regards, tom lane

Okay. Does not getting as many workers as it asks for include
sometimes getting zero, completely changing the actual output? If so,
I'll submit a new version of the patch removing all tests--I was
hoping to improve coverage, but I guess this is not the way to start.
If not, can we keep the json tests at least if we only consider the
first worker?