Thread: auto_explain produces invalid JSON

auto_explain produces invalid JSON

From
Peter Eisentraut
Date:
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.




Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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



Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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

Re: auto_explain produces invalid JSON

From
Tom Lane
Date:
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


Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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





Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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

Re: auto_explain produces invalid JSON

From
Tom Lane
Date:
[ 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


Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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


Re: auto_explain produces invalid JSON

From
Tom Lane
Date:
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


Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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


Re: auto_explain produces invalid JSON

From
Andrew Dunstan
Date:

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