auto_explain produces invalid JSON

Started by Peter Eisentrautalmost 14 years ago11 messages

Peter Eisentraut

peter_e@gmx.net

almost 14 years ago

The auto_explain module appears to create invalid JSON (in all versions
since 9.0). For example, with the settings

auto_explain.log_format = 'json'
auto_explain.log_min_duration = 0

the query

select * from pg_type;

produces this in the log:

LOG: duration: 529.808 ms plan:
[
"Query Text": "select * from pg_type;",
"Plan": {
"Node Type": "Seq Scan",
"Relation Name": "pg_type",
"Alias": "pg_type",
"Startup Cost": 0.00,
"Total Cost": 9.87,
"Plan Rows": 287,
"Plan Width": 611
}
]

Note that at the top level, it uses the array delimiters [ ] for what is
actually an object (key/value). Running this through a JSON parser will
fail.

By contrast, EXPLAIN (FORMAT JSON) on the command line produces:

QUERY PLAN
-----------------------------------
[
{
"Plan": {
"Node Type": "Seq Scan",
"Relation Name": "pg_type",
"Alias": "pg_type",
"Startup Cost": 0.00,
"Total Cost": 9.87,
"Plan Rows": 287,
"Plan Width": 611
}
}
]
(1 row)

So there is evidently something out of sync between what EXPLAIN and
what auto_explain produces.

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Peter Eisentraut (#1)

Re: auto_explain produces invalid JSON

On 02/10/2012 01:14 PM, Peter Eisentraut wrote:

The auto_explain module appears to create invalid JSON (in all versions
since 9.0). For example, with the settings

auto_explain.log_format = 'json'
auto_explain.log_min_duration = 0

the query

select * from pg_type;

produces this in the log:

LOG: duration: 529.808 ms plan:
[
"Query Text": "select * from pg_type;",
"Plan": {
"Node Type": "Seq Scan",
"Relation Name": "pg_type",
"Alias": "pg_type",
"Startup Cost": 0.00,
"Total Cost": 9.87,
"Plan Rows": 287,
"Plan Width": 611
}
]

Note that at the top level, it uses the array delimiters [ ] for what is
actually an object (key/value). Running this through a JSON parser will
fail.

By contrast, EXPLAIN (FORMAT JSON) on the command line produces:

QUERY PLAN
-----------------------------------
[
{
"Plan": {
"Node Type": "Seq Scan",
"Relation Name": "pg_type",
"Alias": "pg_type",
"Startup Cost": 0.00,
"Total Cost": 9.87,
"Plan Rows": 287,
"Plan Width": 611
}
}
]
(1 row)

Yeah, looks like this dates back to when we first got JSON output.

Auto-explain does this:

ExplainBeginOutput(&es);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
ExplainEndOutput(&es);

But ExplainBeginOutput says:

case EXPLAIN_FORMAT_JSON:
/* top-level structure is an array of plans */
appendStringInfoChar(es->str, '[');

Now that's not true in the auto-explain case, which prints one query +
one plan.

Since this is an exposed API, I don't think we can just change it. We
probably need a new API that does the right thing for beginning and
ending auto_explain output. (ExplainBeginLabeledOutput?)

cheers

andrew

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Andrew Dunstan (#2)

1 attachment(s)

Re: auto_explain produces invalid JSON

On 02/11/2012 01:18 PM, Andrew Dunstan wrote:

On 02/10/2012 01:14 PM, Peter Eisentraut wrote:

[ auto-explain JSON output should be an object instead of an array ]

Yeah, looks like this dates back to when we first got JSON output.

Auto-explain does this:

ExplainBeginOutput(&es);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
ExplainEndOutput(&es);

But ExplainBeginOutput says:

case EXPLAIN_FORMAT_JSON:
/* top-level structure is an array of plans */
appendStringInfoChar(es->str, '[');

Now that's not true in the auto-explain case, which prints one query +
one plan.

Since this is an exposed API, I don't think we can just change it. We
probably need a new API that does the right thing for beginning and
ending auto_explain output. (ExplainBeginLabeledOutput?)

PFA a patch along these lines, which seems to do the Right Thing (tm)

cheers

andrew

Attachments:

explain.patchtext/x-patch; name=explain.patchDownload

*** a/contrib/auto_explain/auto_explain.c
--- b/contrib/auto_explain/auto_explain.c
***************
*** 290,299 **** explain_ExecutorEnd(QueryDesc *queryDesc)
  			es.buffers = (es.analyze && auto_explain_log_buffers);
  			es.format = auto_explain_log_format;
  
! 			ExplainBeginOutput(&es);
  			ExplainQueryText(&es, queryDesc);
  			ExplainPrintPlan(&es, queryDesc);
! 			ExplainEndOutput(&es);
  
  			/* Remove last line break */
  			if (es.str->len > 0 && es.str->data[es.str->len - 1] == '\n')
--- 290,299 ----
  			es.buffers = (es.analyze && auto_explain_log_buffers);
  			es.format = auto_explain_log_format;
  
! 			ExplainBeginLabeledOutput(&es);
  			ExplainQueryText(&es, queryDesc);
  			ExplainPrintPlan(&es, queryDesc);
! 			ExplainEndLabeledOutput(&es);
  
  			/* Remove last line break */
  			if (es.str->len > 0 && es.str->data[es.str->len - 1] == '\n')
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
***************
*** 2258,2263 **** ExplainEndOutput(ExplainState *es)
--- 2258,2302 ----
  }
  
  /*
+  * Emit the start-of-output boilerplate, if it's labeled, as auto_explain
+  * JSON is. For non-json cases, fall back on ExplainBeginOutput.
+  *
+  */
+ void
+ ExplainBeginLabeledOutput(ExplainState *es)
+ {
+ 	switch (es->format)
+ 	{
+ 		case EXPLAIN_FORMAT_JSON:
+ 			/* top level is an object of labeled items */
+ 			appendStringInfoChar(es->str, '{');
+ 			es->grouping_stack = lcons_int(0, es->grouping_stack);
+ 			es->indent++;
+ 			break;
+ 		default:
+ 			ExplainBeginOutput(es);
+ 	}
+ }
+ 
+ /* 
+  * Companion to ExplainBeginLabeledOutput
+  */
+ void
+ ExplainEndLabeledOutput(ExplainState *es)
+ {
+ 	switch (es->format)
+ 	{
+ 		case EXPLAIN_FORMAT_JSON:
+ 			es->indent--;
+ 			appendStringInfoString(es->str, "\n}");
+ 			es->grouping_stack = list_delete_first(es->grouping_stack);
+ 			break;
+ 		default:
+ 			ExplainEndOutput(es);
+ 	}
+ }
+ 
+ /*
   * Put an appropriate separator between multiple plans
   */
  void
*** a/src/include/commands/explain.h
--- b/src/include/commands/explain.h
***************
*** 71,76 **** extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
--- 71,78 ----
  
  extern void ExplainBeginOutput(ExplainState *es);
  extern void ExplainEndOutput(ExplainState *es);
+ extern void ExplainBeginLabeledOutput(ExplainState *es);
+ extern void ExplainEndLabeledOutput(ExplainState *es);
  extern void ExplainSeparatePlans(ExplainState *es);
  
  extern void ExplainPropertyList(const char *qlabel, List *data,

Tom Lane

tgl@sss.pgh.pa.us

almost 14 years ago

In reply to: Andrew Dunstan (#2)

Re: auto_explain produces invalid JSON

Andrew Dunstan <andrew@dunslane.net> writes:

But ExplainBeginOutput says:

case EXPLAIN_FORMAT_JSON:
/* top-level structure is an array of plans */
appendStringInfoChar(es->str, '[');

Now that's not true in the auto-explain case, which prints one query +
one plan.

What about queries that expand to multiple plans because of rules?

Since this is an exposed API, I don't think we can just change it. We
probably need a new API that does the right thing for beginning and
ending auto_explain output. (ExplainBeginLabeledOutput?)

I'm inclined to think that this is auto_explain's error, not that of
the core code, ie we should be changing the output.

regards, tom lane

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Tom Lane (#4)

Re: auto_explain produces invalid JSON

On 02/11/2012 03:22 PM, Tom Lane wrote:

Andrew Dunstan<andrew@dunslane.net> writes:

But ExplainBeginOutput says:
case EXPLAIN_FORMAT_JSON:
/* top-level structure is an array of plans */
appendStringInfoChar(es->str, '[');
Now that's not true in the auto-explain case, which prints one query +
one plan.

What about queries that expand to multiple plans because of rules?

Oh, hmm, good point.

Since this is an exposed API, I don't think we can just change it. We
probably need a new API that does the right thing for beginning and
ending auto_explain output. (ExplainBeginLabeledOutput?)

I'm inclined to think that this is auto_explain's error, not that of
the core code, ie we should be changing the output.

It looks like it will be messy either way. ;-(

cheers

andrew

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Tom Lane (#4)

1 attachment(s)

Re: auto_explain produces invalid JSON

On 02/11/2012 03:22 PM, Tom Lane wrote:

Andrew Dunstan<andrew@dunslane.net> writes:

But ExplainBeginOutput says:
case EXPLAIN_FORMAT_JSON:
/* top-level structure is an array of plans */
appendStringInfoChar(es->str, '[');
Now that's not true in the auto-explain case, which prints one query +
one plan.

What about queries that expand to multiple plans because of rules?

... and the answer is it logs them in separate pieces of JSON.

Since this is an exposed API, I don't think we can just change it. We
probably need a new API that does the right thing for beginning and
ending auto_explain output. (ExplainBeginLabeledOutput?)

I'm inclined to think that this is auto_explain's error, not that of
the core code, ie we should be changing the output.

Well, maybe this is more to your taste, although it strikes me as more
than something of a kludge. At least it's short :-)

cheers

andrew

Attachments:

explain2.patchtext/x-patch; name=explain2.patchDownload

*** a/contrib/auto_explain/auto_explain.c
--- b/contrib/auto_explain/auto_explain.c
***************
*** 299,304 **** explain_ExecutorEnd(QueryDesc *queryDesc)
--- 299,311 ----
  			if (es.str->len > 0 && es.str->data[es.str->len - 1] == '\n')
  				es.str->data[--es.str->len] = '\0';
  
+ 			/* Fix JSON to output an object */
+ 			if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
+ 			{
+ 				es.str->data[0] = '{';
+ 				es.str->data[es.str->len - 1] = '}';
+ 			}
+ 
  			/*
  			 * Note: we rely on the existing logging of context or
  			 * debug_query_string to identify just which statement is being

Tom Lane

tgl@sss.pgh.pa.us

almost 14 years ago

In reply to: Andrew Dunstan (#6)

Re: auto_explain produces invalid JSON

[ sorry for ignoring this over the weekend --- I wasn't feeling very well ]

Andrew Dunstan <andrew@dunslane.net> writes:

On 02/11/2012 03:22 PM, Tom Lane wrote:

I'm inclined to think that this is auto_explain's error, not that of
the core code, ie we should be changing the output.

Well, maybe this is more to your taste, although it strikes me as more
than something of a kludge. At least it's short :-)

I see you've already committed this, but I agree that it's quite a
kluge.

After looking a bit more at the existing explain code, it seems like the
critical issue is that explain.c has ExplainOpenGroup/ExplainCloseGroup
calls around the ExplainPrintPlan call (see ExplainOnePlan), while
auto_explain does not. I did not like your originally proposed patch
because it seemed to introduce yet another formatting concept into code
that has already got a few too many. But couldn't we fix this by
exporting ExplainOpenGroup/ExplainCloseGroup and then calling those from
auto_explain?

regards, tom lane

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Tom Lane (#7)

Re: auto_explain produces invalid JSON

On 02/13/2012 11:15 AM, Tom Lane wrote:

[ sorry for ignoring this over the weekend --- I wasn't feeling very well ]

Andrew Dunstan<andrew@dunslane.net> writes:

On 02/11/2012 03:22 PM, Tom Lane wrote:

I'm inclined to think that this is auto_explain's error, not that of
the core code, ie we should be changing the output.

Well, maybe this is more to your taste, although it strikes me as more
than something of a kludge. At least it's short :-)

I see you've already committed this, but I agree that it's quite a
kluge.

After looking a bit more at the existing explain code, it seems like the
critical issue is that explain.c has ExplainOpenGroup/ExplainCloseGroup
calls around the ExplainPrintPlan call (see ExplainOnePlan), while
auto_explain does not. I did not like your originally proposed patch
because it seemed to introduce yet another formatting concept into code
that has already got a few too many. But couldn't we fix this by
exporting ExplainOpenGroup/ExplainCloseGroup and then calling those from
auto_explain?

Yeah, maybe. We'd still have to do it conditionally (have to use
ExplainBeginOutput for the XML case), but it would possibly be less kludgy.

cheers

andrew

Tom Lane

tgl@sss.pgh.pa.us

almost 14 years ago

In reply to: Andrew Dunstan (#8)

Re: auto_explain produces invalid JSON

Andrew Dunstan <andrew@dunslane.net> writes:

On 02/13/2012 11:15 AM, Tom Lane wrote:

After looking a bit more at the existing explain code, it seems like the
critical issue is that explain.c has ExplainOpenGroup/ExplainCloseGroup
calls around the ExplainPrintPlan call (see ExplainOnePlan), while
auto_explain does not.

Yeah, maybe. We'd still have to do it conditionally (have to use
ExplainBeginOutput for the XML case), but it would possibly be less kludgy.

Hm? I wasn't suggesting removing the ExplainBeginOutput call, but more
like

ExplainBeginOutput(&es);
+ ExplainOpenGroup(...);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
+ ExplainCloseGroup(...);
ExplainEndOutput(&es);

Details still TBD; the point is just that it's not clear to me why
auto_explain should need a formatting concept that doesn't already exist
within explain.c.

regards, tom lane

#10

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Tom Lane (#9)

Re: auto_explain produces invalid JSON

On 02/13/2012 12:48 PM, Tom Lane wrote:

Andrew Dunstan<andrew@dunslane.net> writes:

On 02/13/2012 11:15 AM, Tom Lane wrote:

After looking a bit more at the existing explain code, it seems like the
critical issue is that explain.c has ExplainOpenGroup/ExplainCloseGroup
calls around the ExplainPrintPlan call (see ExplainOnePlan), while
auto_explain does not.

Yeah, maybe. We'd still have to do it conditionally (have to use
ExplainBeginOutput for the XML case), but it would possibly be less kludgy.

Hm? I wasn't suggesting removing the ExplainBeginOutput call, but more
like

ExplainBeginOutput(&es);
+ ExplainOpenGroup(...);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
+ ExplainCloseGroup(...);
ExplainEndOutput(&es);

Details still TBD; the point is just that it's not clear to me why
auto_explain should need a formatting concept that doesn't already exist
within explain.c.

This will introduce an extra level of nesting for no good reason.

But this would work:

-           ExplainBeginOutput(&es);
+           if (auto_explain_log_format != EXPLAIN_FORMAT_JSON)
+               ExplainBeginOutput(&es);
+           else
+               ExplainOpenGroup(NULL, NULL, true,& es);
             ExplainQueryText(&es, queryDesc);
             ExplainPrintPlan(&es, queryDesc);
-           ExplainEndOutput(&es);
+           if (auto_explain_log_format != EXPLAIN_FORMAT_JSON)
+               ExplainEndOutput(&es);
+           else
+               ExplainCloseGroup(NULL, NULL, true, &es);

cheers

andrew

#11

Andrew Dunstan

andrew@dunslane.net

almost 14 years ago

In reply to: Andrew Dunstan (#10)

Re: auto_explain produces invalid JSON

On 02/13/2012 01:33 PM, Andrew Dunstan wrote:

On 02/13/2012 12:48 PM, Tom Lane wrote:

Andrew Dunstan<andrew@dunslane.net> writes:

On 02/13/2012 11:15 AM, Tom Lane wrote:

After looking a bit more at the existing explain code, it seems
like the
critical issue is that explain.c has
ExplainOpenGroup/ExplainCloseGroup
calls around the ExplainPrintPlan call (see ExplainOnePlan), while
auto_explain does not.

Yeah, maybe. We'd still have to do it conditionally (have to use
ExplainBeginOutput for the XML case), but it would possibly be less
kludgy.

Hm? I wasn't suggesting removing the ExplainBeginOutput call, but more
like

ExplainBeginOutput(&es);
+ ExplainOpenGroup(...);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
+ ExplainCloseGroup(...);
ExplainEndOutput(&es);

Details still TBD; the point is just that it's not clear to me why
auto_explain should need a formatting concept that doesn't already exist
within explain.c.

This will introduce an extra level of nesting for no good reason.

But this would work:
-           ExplainBeginOutput(&es);
+           if (auto_explain_log_format != EXPLAIN_FORMAT_JSON)
+               ExplainBeginOutput(&es);
+           else
+               ExplainOpenGroup(NULL, NULL, true,& es);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
-           ExplainEndOutput(&es);
+           if (auto_explain_log_format != EXPLAIN_FORMAT_JSON)
+               ExplainEndOutput(&es);
+           else
+               ExplainCloseGroup(NULL, NULL, true, &es);

Except that it causes other problems.

I think we'd probably bet sleeping dogs lie.

cheers

andrew