Thread: auto_explain produces invalid JSON
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": {
"NodeType": "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.
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
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
Attachment
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
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
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
Attachment
[ 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
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
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
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
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