Thread

1. auto_explain produces invalid JSON

   Peter Eisentraut <peter_e@gmx.net> — 2012-02-10T18:14:28Z

   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.
   
   
   
   

2. Re: auto_explain produces invalid JSON

   Andrew Dunstan <andrew@dunslane.net> — 2012-02-11T18:18:59Z

   
   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
   
   
   

3. Re: auto_explain produces invalid JSON

   Andrew Dunstan <andrew@dunslane.net> — 2012-02-11T20:12:01Z

   
   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
   
   
   

4. Re: auto_explain produces invalid JSON

   Tom Lane <tgl@sss.pgh.pa.us> — 2012-02-11T20:22:11Z

   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
   
   

5. Re: auto_explain produces invalid JSON

   Andrew Dunstan <andrew@dunslane.net> — 2012-02-11T21:26:55Z

   
   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
   
   
   
   
   

6. Re: auto_explain produces invalid JSON

   Andrew Dunstan <andrew@dunslane.net> — 2012-02-11T21:56:15Z

   
   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
   
   

7. Re: auto_explain produces invalid JSON

   Tom Lane <tgl@sss.pgh.pa.us> — 2012-02-13T16:15:10Z

   [ 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
   
   

8. Re: auto_explain produces invalid JSON

   Andrew Dunstan <andrew@dunslane.net> — 2012-02-13T17:42:46Z

   
   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
   
   

9. Re: auto_explain produces invalid JSON

   Tom Lane <tgl@sss.pgh.pa.us> — 2012-02-13T17:48:52Z

   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. Re: auto_explain produces invalid JSON

    Andrew Dunstan <andrew@dunslane.net> — 2012-02-13T18:33:58Z

    
    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. Re: auto_explain produces invalid JSON

    Andrew Dunstan <andrew@dunslane.net> — 2012-02-13T19:11:54Z

    
    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