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": {
"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.

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

Andrew Dunstan <andrew(at)dunslane(dot)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(at)dunslane(dot)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(at)dunslane(dot)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

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

Andrew Dunstan <andrew(at)dunslane(dot)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(at)dunslane(dot)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(at)dunslane(dot)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(at)dunslane(dot)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(at)dunslane(dot)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