From: Tom Lane <tgl@sss.pgh.pa.us>
To: Hamid Akhtar <hamid.akhtar@gmail.com>
cc: pgsql-hackers@lists.postgresql.org, Daniel Gustafsson <daniel@yesql.se>
Subject: Re: BUG #16171: Potential malformed JSON in explain output
In-reply-to: 
 <157985813081.742.12901374861257824963.pgcf@coridan.postgresql.org>
References: <16171-b72259ab75505fa2@postgresql.org>
 <495433FC-A268-4956-9B61-5FB135EE5B73@yesql.se>
 <157985813081.742.12901374861257824963.pgcf@coridan.postgresql.org>
Comments: In-reply-to Hamid Akhtar <hamid.akhtar@gmail.com>
	message dated "Fri, 24 Jan 2020 09:28:50 +0000"
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <9261.1580585732.0@sss.pgh.pa.us>
Date: Sat, 01 Feb 2020 14:37:55 -0500
Message-ID: <9342.1580585875@sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <9261.1580585732.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable

Hamid Akhtar <hamid.akhtar@gmail.com> writes:
> I've reviewed and verified this patch and IMHO, this is ready to be comm=
itted.

I took a look at this and I don't think it's really going in the right
direction.  ISTM the clear intent of this code was to attach the "Subplans
Removed" item as a field of the parent [Merge]Append node, but the author
forgot about the intermediate "Plans" array.  So I think that, rather than
doubling down on a mistake, we ought to move where the field is generated
so that it *is* a field of the parent node.

Another failure to follow the design conventions for EXPLAIN output is
that in non-text formats, the schema for each node type ought to be fixed;
that is, if a given field can appear for a particular node type and
EXPLAIN options, it should appear always, not be omitted just because it's
zero.

So that leads me to propose 0001 attached.  This does lead to some field
order rearrangement in text mode, as per the regression test changes,
but I think that's not a big deal.  (A change can only happen if there
are initplan(s) attached to the parent node.)

Also, I wondered whether we had any other violations of correct formatting
in this code, which led me to the idea of running auto_explain in JSON
mode and having it feed its result to json_in.  This isn't a complete
test because it won't whine about duplicate field names, but it did
correctly find the current bug --- and I couldn't find any others while
running the core regression tests with various auto_explain options.
0002 attached isn't committable, because nobody would want the overhead
in production, but it seems like a good trick to keep up our sleeves.

Thoughts?

			regards, tom lane


------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="0001-place-subnodes-removed-correctly.patch";
	charset="us-ascii"
Content-ID: <9261.1580585732.2@sss.pgh.pa.us>
Content-Description: 0001-place-subnodes-removed-correctly.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain=
.c
index c367c75..d901dc4 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -119,8 +119,9 @@ static void ExplainModifyTarget(ModifyTable *plan, Exp=
lainState *es);
 static void ExplainTargetRel(Plan *plan, Index rti, ExplainState *es);
 static void show_modifytable_info(ModifyTableState *mtstate, List *ancest=
ors,
 								  ExplainState *es);
-static void ExplainMemberNodes(PlanState **planstates, int nsubnodes,
-							   int nplans, List *ancestors, ExplainState *es);
+static void ExplainMemberNodes(PlanState **planstates, int nplans,
+							   List *ancestors, ExplainState *es);
+static void ExplainMissingMembers(int nplans, int nchildren, ExplainState=
 *es);
 static void ExplainSubPlans(List *plans, List *ancestors,
 							const char *relationship, ExplainState *es);
 static void ExplainCustomChildren(CustomScanState *css,
@@ -1967,6 +1968,30 @@ ExplainNode(PlanState *planstate, List *ancestors,
 		ExplainFlushWorkersState(es);
 	es->workers_state =3D save_workers_state;
 =

+	/*
+	 * If partition pruning was done during executor initialization, the
+	 * number of child plans we'll display below will be less than the numbe=
r
+	 * of subplans that was specified in the plan.  To make this a bit less
+	 * mysterious, emit an indication that this happened.  Note that this
+	 * field is emitted now because we want it to be a property of the paren=
t
+	 * node; it *cannot* be emitted within the Plans sub-node we'll open nex=
t.
+	 */
+	switch (nodeTag(plan))
+	{
+		case T_Append:
+			ExplainMissingMembers(((AppendState *) planstate)->as_nplans,
+								  list_length(((Append *) plan)->appendplans),
+								  es);
+			break;
+		case T_MergeAppend:
+			ExplainMissingMembers(((MergeAppendState *) planstate)->ms_nplans,
+								  list_length(((MergeAppend *) plan)->mergeplans),
+								  es);
+			break;
+		default:
+			break;
+	}
+
 	/* Get ready to display the child plans */
 	haschildren =3D planstate->initPlan ||
 		outerPlanState(planstate) ||
@@ -2007,31 +2032,26 @@ ExplainNode(PlanState *planstate, List *ancestors,
 		case T_ModifyTable:
 			ExplainMemberNodes(((ModifyTableState *) planstate)->mt_plans,
 							   ((ModifyTableState *) planstate)->mt_nplans,
-							   list_length(((ModifyTable *) plan)->plans),
 							   ancestors, es);
 			break;
 		case T_Append:
 			ExplainMemberNodes(((AppendState *) planstate)->appendplans,
 							   ((AppendState *) planstate)->as_nplans,
-							   list_length(((Append *) plan)->appendplans),
 							   ancestors, es);
 			break;
 		case T_MergeAppend:
 			ExplainMemberNodes(((MergeAppendState *) planstate)->mergeplans,
 							   ((MergeAppendState *) planstate)->ms_nplans,
-							   list_length(((MergeAppend *) plan)->mergeplans),
 							   ancestors, es);
 			break;
 		case T_BitmapAnd:
 			ExplainMemberNodes(((BitmapAndState *) planstate)->bitmapplans,
 							   ((BitmapAndState *) planstate)->nplans,
-							   list_length(((BitmapAnd *) plan)->bitmapplans),
 							   ancestors, es);
 			break;
 		case T_BitmapOr:
 			ExplainMemberNodes(((BitmapOrState *) planstate)->bitmapplans,
 							   ((BitmapOrState *) planstate)->nplans,
-							   list_length(((BitmapOr *) plan)->bitmapplans),
 							   ancestors, es);
 			break;
 		case T_SubqueryScan:
@@ -3348,33 +3368,34 @@ show_modifytable_info(ModifyTableState *mtstate, L=
ist *ancestors,
  *
  * The ancestors list should already contain the immediate parent of thes=
e
  * plans.
-*
-* nsubnodes indicates the number of items in the planstates array.
-* nplans indicates the original number of subnodes in the Plan, some of t=
hese
-* may have been pruned by the run-time pruning code.
  */
 static void
-ExplainMemberNodes(PlanState **planstates, int nsubnodes, int nplans,
+ExplainMemberNodes(PlanState **planstates, int nplans,
 				   List *ancestors, ExplainState *es)
 {
 	int			j;
 =

-	/*
-	 * The number of subnodes being lower than the number of subplans that w=
as
-	 * specified in the plan means that some subnodes have been ignored per
-	 * instruction for the partition pruning code during the executor
-	 * initialization.  To make this a bit less mysterious, we'll indicate
-	 * here that this has happened.
-	 */
-	if (nsubnodes < nplans)
-		ExplainPropertyInteger("Subplans Removed", NULL, nplans - nsubnodes, es=
);
-
-	for (j =3D 0; j < nsubnodes; j++)
+	for (j =3D 0; j < nplans; j++)
 		ExplainNode(planstates[j], ancestors,
 					"Member", NULL, es);
 }
 =

 /*
+ * Report about any pruned subnodes of an Append or MergeAppend node.
+ *
+ * nplans indicates the number of live subplans.
+ * nchildren indicates the original number of subnodes in the Plan;
+ * some of these may have been pruned by the run-time pruning code.
+ */
+static void
+ExplainMissingMembers(int nplans, int nchildren, ExplainState *es)
+{
+	if (nplans < nchildren || es->format !=3D EXPLAIN_FORMAT_TEXT)
+		ExplainPropertyInteger("Subplans Removed", NULL,
+							   nchildren - nplans, es);
+}
+
+/*
  * Explain a list of SubPlans (or initPlans, which also use SubPlan nodes=
).
  *
  * The ancestors list should already contain the immediate parent of thes=
e
diff --git a/src/test/regress/expected/partition_prune.out b/src/test/regr=
ess/expected/partition_prune.out
index 424d51d..9c8f80d 100644
--- a/src/test/regress/expected/partition_prune.out
+++ b/src/test/regress/expected/partition_prune.out
@@ -1808,9 +1808,9 @@ explain (analyze, costs off, summary off, timing off=
) execute ab_q2 (2, 2);
                        QUERY PLAN                        =

 ---------------------------------------------------------
  Append (actual rows=3D0 loops=3D1)
+   Subplans Removed: 6
    InitPlan 1 (returns $0)
      ->  Result (actual rows=3D1 loops=3D1)
-   Subplans Removed: 6
    ->  Seq Scan on ab_a2_b1 ab_1 (actual rows=3D0 loops=3D1)
          Filter: ((a >=3D $1) AND (a <=3D $2) AND (b < $0))
    ->  Seq Scan on ab_a2_b2 ab_2 (actual rows=3D0 loops=3D1)
@@ -1826,9 +1826,9 @@ explain (analyze, costs off, summary off, timing off=
) execute ab_q3 (2, 2);
                        QUERY PLAN                        =

 ---------------------------------------------------------
  Append (actual rows=3D0 loops=3D1)
+   Subplans Removed: 6
    InitPlan 1 (returns $0)
      ->  Result (actual rows=3D1 loops=3D1)
-   Subplans Removed: 6
    ->  Seq Scan on ab_a1_b2 ab_1 (actual rows=3D0 loops=3D1)
          Filter: ((b >=3D $1) AND (b <=3D $2) AND (a < $0))
    ->  Seq Scan on ab_a2_b2 ab_2 (actual rows=3D0 loops=3D1)
@@ -2396,9 +2396,9 @@ explain (analyze, costs off, summary off, timing off=
) execute ab_q6(1);
                     QUERY PLAN                    =

 --------------------------------------------------
  Append (actual rows=3D0 loops=3D1)
+   Subplans Removed: 12
    InitPlan 1 (returns $0)
      ->  Result (actual rows=3D1 loops=3D1)
-   Subplans Removed: 12
    ->  Seq Scan on ab_a1_b1 ab_1 (never executed)
          Filter: ((a =3D $1) AND (b =3D $0))
    ->  Seq Scan on ab_a1_b2 ab_2 (never executed)
@@ -3032,9 +3032,9 @@ execute ps1(1);
                        QUERY PLAN                       =

 --------------------------------------------------------
  Append (actual rows=3D1 loops=3D1)
+   Subplans Removed: 2
    InitPlan 1 (returns $0)
      ->  Result (actual rows=3D1 loops=3D1)
-   Subplans Removed: 2
    ->  Seq Scan on mc3p1 mc3p_1 (actual rows=3D1 loops=3D1)
          Filter: ((a =3D $1) AND (abs(b) < $0))
 (6 rows)
@@ -3047,9 +3047,9 @@ execute ps2(1);
                        QUERY PLAN                       =

 --------------------------------------------------------
  Append (actual rows=3D2 loops=3D1)
+   Subplans Removed: 1
    InitPlan 1 (returns $0)
      ->  Result (actual rows=3D1 loops=3D1)
-   Subplans Removed: 1
    ->  Seq Scan on mc3p0 mc3p_1 (actual rows=3D1 loops=3D1)
          Filter: ((a <=3D $1) AND (abs(b) < $0))
    ->  Seq Scan on mc3p1 mc3p_2 (actual rows=3D1 loops=3D1)
@@ -3594,9 +3594,9 @@ explain (costs off) execute q (1, 1);
                           QUERY PLAN                           =

 ---------------------------------------------------------------
  Append
+   Subplans Removed: 1
    InitPlan 1 (returns $0)
      ->  Result
-   Subplans Removed: 1
    ->  Seq Scan on p1 p
          Filter: ((a =3D $1) AND (b =3D $2) AND (c =3D $0))
    ->  Seq Scan on q111 q1

------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="0002-check-json-validity.patch";
	charset="us-ascii"
Content-ID: <9261.1580585732.3@sss.pgh.pa.us>
Content-Description: 0002-check-json-validity.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/au=
to_explain.c
index f69dde8..71cb4fa 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -18,6 +18,7 @@
 #include "commands/explain.h"
 #include "executor/instrument.h"
 #include "jit/jit.h"
+#include "utils/builtins.h"
 #include "utils/guc.h"
 =

 PG_MODULE_MAGIC;
@@ -397,6 +398,10 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 			{
 				es->str->data[0] =3D '{';
 				es->str->data[es->str->len - 1] =3D '}';
+
+				/* Verify that it's valid JSON by feeding to json_in */
+				(void) DirectFunctionCall1(json_in,
+										   CStringGetDatum(es->str->data));
 			}
 =

 			/*

------- =_aaaaaaaaaa0--