Обсуждение: WIP: log query in auto-explain

I put the attached together a while ago and neglected to send it.
Basically it includes the text of the query being explained in the
explain output.

I think it's more important to include the query text when using
auto_explain than in other explain uses, which is why I did it this way.
But I could be persuaded that we should always include it.

Thoughts? Comments?

cheers

andrew
Index: src/include/commands/explain.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/commands/explain.h,v
retrieving revision 1.41
diff -c -r1.41 explain.h
*** src/include/commands/explain.h    10 Aug 2009 05:46:50 -0000    1.41
--- src/include/commands/explain.h    22 Nov 2009 19:50:13 -0000
***************
*** 54,59 ****
--- 54,63 ----

  extern void ExplainInitState(ExplainState *es);

+ extern void ExplainBeginOutput(ExplainState *es);
+
+ extern void ExplainEndOutput(ExplainState *es);
+
  extern TupleDesc ExplainResultDesc(ExplainStmt *stmt);

  extern void ExplainOneUtility(Node *utilityStmt, ExplainState *es,
***************
*** 62,67 ****
--- 66,73 ----
  extern void ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
                 const char *queryString, ParamListInfo params);

+ extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
+
  extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);

  extern void ExplainSeparatePlans(ExplainState *es);
Index: src/backend/commands/explain.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/explain.c,v
retrieving revision 1.193
diff -c -r1.193 explain.c
*** src/backend/commands/explain.c    4 Nov 2009 22:26:04 -0000    1.193
--- src/backend/commands/explain.c    22 Nov 2009 19:50:13 -0000
***************
*** 91,98 ****
                   bool labeled, ExplainState *es);
  static void ExplainDummyGroup(const char *objtype, const char *labelname,
                                ExplainState *es);
- static void ExplainBeginOutput(ExplainState *es);
- static void ExplainEndOutput(ExplainState *es);
  static void ExplainXMLTag(const char *tagname, int flags, ExplainState *es);
  static void ExplainJSONLineEnding(ExplainState *es);
  static void escape_json(StringInfo buf, const char *str);
--- 91,96 ----
***************
*** 469,474 ****
--- 467,486 ----
  }

  /*
+  * ExplainQueryText -
+  *    add a "Query Text" node that conatins the actual text of the query
+  *
+  * The caller should have set up the options fields of *es, as well as
+  * initializing the output buffer es->str.
+  *
+  */
+ void
+ ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
+ {
+     ExplainPropertyText("Query Text", queryDesc->sourceText, es);
+ }
+
+ /*
   * report_triggers -
   *        report execution stats for a single relation's triggers
   */
***************
*** 1738,1744 ****
   * This is just enough different from processing a subgroup that we need
   * a separate pair of subroutines.
   */
! static void
  ExplainBeginOutput(ExplainState *es)
  {
      switch (es->format)
--- 1750,1756 ----
   * This is just enough different from processing a subgroup that we need
   * a separate pair of subroutines.
   */
! void
  ExplainBeginOutput(ExplainState *es)
  {
      switch (es->format)
***************
*** 1765,1771 ****
  /*
   * Emit the end-of-output boilerplate.
   */
! static void
  ExplainEndOutput(ExplainState *es)
  {
      switch (es->format)
--- 1777,1783 ----
  /*
   * Emit the end-of-output boilerplate.
   */
! void
  ExplainEndOutput(ExplainState *es)
  {
      switch (es->format)
Index: contrib/auto_explain/auto_explain.c
===================================================================
RCS file: /cvsroot/pgsql/contrib/auto_explain/auto_explain.c,v
retrieving revision 1.7
diff -c -r1.7 auto_explain.c
*** contrib/auto_explain/auto_explain.c    10 Aug 2009 05:46:49 -0000    1.7
--- contrib/auto_explain/auto_explain.c    22 Nov 2009 19:50:13 -0000
***************
*** 222,228 ****
--- 222,231 ----
              es.verbose = auto_explain_log_verbose;
              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')
***************
*** 236,242 ****
               */
              ereport(LOG,
                      (errmsg("duration: %.3f ms  plan:\n%s",
!                             msec, es.str->data)));

              pfree(es.str->data);
          }
--- 239,246 ----
               */
              ereport(LOG,
                      (errmsg("duration: %.3f ms  plan:\n%s",
!                             msec, es.str->data),
!                      errhidestmt(true)));

              pfree(es.str->data);
          }

Andrew Dunstan <andrew@dunslane.net> writes:
> I put the attached together a while ago and neglected to send it. 
> Basically it includes the text of the query being explained in the 
> explain output.

I'm pretty certain this will dump core in some contexts --- you should
not assume that sourceText is always available.

Should we be worried about security implications of displaying the query
text?

> I think it's more important to include the query text when using 
> auto_explain than in other explain uses, which is why I did it this way. 
> But I could be persuaded that we should always include it.

I think this is just useless noise in every other case.
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> I put the attached together a while ago and neglected to send it. 
>> Basically it includes the text of the query being explained in the 
>> explain output.
>>     
>
> I'm pretty certain this will dump core in some contexts --- you should
> not assume that sourceText is always available.
>   

Ok, I guess I can insert a check that the sourceText is not null. I 
wonder what we are supposed to take an explanation to mean if we can't 
say what it is we're explaining.

> Should we be worried about security implications of displaying the query
> text?
>
>   

If it is dangerous then surely so is the explanation.

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> wrote:

> Basically it includes the text of the query being explained in the 
> explain output.

I expected the query text is printed in "STATEMENT" section.
Do you mean the query should be merged into "LOG" section?
Are there any situation where "STATEMENT" section does not work?

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro wrote:
> Andrew Dunstan <andrew@dunslane.net> wrote:
>
>   
>> Basically it includes the text of the query being explained in the 
>> explain output.
>>     
>
> I expected the query text is printed in "STATEMENT" section.
> Do you mean the query should be merged into "LOG" section?
> Are there any situation where "STATEMENT" section does not work?
>   


I mean it should be in the Explain output:
   <explain xmlns="http://www.postgresql.org/2009/explain">     <Query-Text>SELECT '' AS zero, BOOLTBL1.*      FROM
BOOLTBL1     WHERE booleq(bool 'false', f1);</Query-Text>     <Plan>       <Node-Type>Seq Scan</Node-Type>
<Relation-Name>booltbl1</Relation-Name>      <Alias>booltbl1</Alias>       <Startup-Cost>0.00</Startup-Cost>
<Total-Cost>42.88</Total-Cost>      <Plan-Rows>877</Plan-Rows>       <Plan-Width>1</Plan-Width>
<Filter>booleq(false,f1)</Filter>     </Plan>   </explain>
 

This is especially important for structured output like XML and/or JSON. 
A number of users (including me) badly want to be able to extract the 
explain output from the log files with the query text included.

cheers

andrew


>   

Andrew Dunstan <andrew@dunslane.net> wrote:

> I mean it should be in the Explain output:
>     <explain xmlns="http://www.postgresql.org/2009/explain">
>       <Query-Text>SELECT '' AS zero, BOOLTBL1.*
> A number of users (including me) badly want to be able to extract the 
> explain output from the log files with the query text included.

I see it's useful for non-text output format.
+1 for the extension.

Also please include the documentation fix because it contains
a sample output using STATEMENT section.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center