Re: [HACKERS] [PATCHES] log_statement output for protocol - Mailing list pgsql-jdbc

Guillaume Smet wrote:
> On 8/7/06, Bruce Momjian <bruce@momjian.us> wrote:
> > Updated patch attached.  It prints the text bind parameters on a single
> > detail line.  I still have not seen portal names generated by libpq.
>
> I'm currently testing CVS tip to generate sample log files. I noticed
> that Bruce only patched log_statement and not
> log_min_duration_statement which still has the old behaviour ie:
> [1-1] LOG:  duration: 0.097 ms  execute my_query:  SELECT * FROM shop
> WHERE name = $1
> The problem of not having the bind parameters still remains.
>
> A lot of people use log_min_duration_statement and it's usually
> recommended to use it instead of log_statement because log_statement
> generates far too much output.
> I tried to find a way to fix it but it's not so simple as when we bind
> the statement, we don't know if the query will be slower than
> log_min_duration_statement.
>
> My first idea is that we should add a DETAIL line with the parameter
> values to the execute log line when we are in the
> log_min_duration_statement case. AFAICS the values are in the portal
> but I don't know the overhead introduced by generating the detail line
> from the portal.
>
> Does anyone have a better idea on how we could fix it?

Yes, I do.  I have applied the attached patch to fix this issue and
several others.  The fix was to save the bind parameters in the portal,
and display those in the executor output, if available.

The other changes were to use single quotes for bind values, instead of
double quotes, and double literal single quotes in bind values (and
document that).  I also made use of the DETAIL line to have much cleaner
output.

With the new output, bind displays prepare as detail, and execute
displays prepare and optionally bind.  I re-added the "statement:" label
so people will understand why the line is being printed (it is
log_*statement behavior).  I am now happy that the display is clear and
not cluttered.

    -- SQL using log_statement
    LOG:  set log_statement = 'all';
    LOG:  statement: begin;
    LOG:  statement: prepare x as select $1::text;
    LOG:  statement: execute x ('a');
    DETAIL:  prepare: prepare x as select $1::text;
    LOG:  statement: commit;

    -- SQL using log_min_duration_statement
    LOG:  statement: set log_statement = 'none';
    LOG:  duration: 0.242 ms  statement: set log_min_duration_statement = 0;
    LOG:  duration: 0.155 ms  statement: begin;
    LOG:  duration: 0.174 ms  statement: prepare y as select $1::text;
    LOG:  duration: 0.252 ms  statement: execute y ('a');
    DETAIL:  prepare: prepare y as select $1::text;
    LOG:  duration: 0.093 ms  statement: commit;

    -- protocol using log_statement
    LOG:  statement: prepare sel1, SELECT $1;
    LOG:  statement: bind sel1, $1 = 'a''b'
    DETAIL:  prepare: SELECT $1;
    LOG:  statement: execute sel1
    DETAIL:  prepare: SELECT $1;  bind: $1 = 'a''b'

    -- protocol using log_min_duration_statement
    LOG:  duration: 0.497 ms  statement: SET log_min_duration_statement = 0;
    LOG:  duration: 0.027 ms  execute sel1
    DETAIL:  prepare: SELECT $1;  bind: $1 = 'a''b'

The last output doesn't have bind or prepare because we don't print
those because we don't do any duration timing for them.  Should we print
the statement: lines of log_min_duration_statement == 0?

Also, this code assumes that a protocol bind and execute always has
prepared statement text, which I believe is true.

The use of brackets is gone.  :-)

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.75
diff -c -c -r1.75 config.sgml
*** doc/src/sgml/config.sgml    17 Aug 2006 23:04:03 -0000    1.75
--- doc/src/sgml/config.sgml    28 Aug 2006 23:59:41 -0000
***************
*** 2839,2845 ****
          prepare, bind, and execute commands are logged only if
          <varname>log_statement</> is <literal>all</>.  Bind parameter
          values are also logged if they are supplied in <literal>text</>
!         format.
         </para>
         <para>
          The default is <literal>none</>. Only superusers can change this
--- 2839,2845 ----
          prepare, bind, and execute commands are logged only if
          <varname>log_statement</> is <literal>all</>.  Bind parameter
          values are also logged if they are supplied in <literal>text</>
!         format (literal single quotes are doubled).
         </para>
         <para>
          The default is <literal>none</>. Only superusers can change this
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.50
diff -c -c -r1.50 portalcmds.c
*** src/backend/commands/portalcmds.c    12 Aug 2006 20:05:54 -0000    1.50
--- src/backend/commands/portalcmds.c    28 Aug 2006 23:59:42 -0000
***************
*** 114,119 ****
--- 114,120 ----
      PortalDefineQuery(portal,
                        NULL,
                        pstrdup(debug_query_string),
+                       NULL,
                        "SELECT", /* cursor's query is always a SELECT */
                        list_make1(query),
                        list_make1(plan),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.61
diff -c -c -r1.61 prepare.c
*** src/backend/commands/prepare.c    14 Aug 2006 22:57:15 -0000    1.61
--- src/backend/commands/prepare.c    28 Aug 2006 23:59:42 -0000
***************
*** 203,208 ****
--- 203,209 ----
      PortalDefineQuery(portal,
                        NULL,
                        query_string,
+                       NULL,
                        entry->commandTag,
                        query_list,
                        plan_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.157
diff -c -c -r1.157 spi.c
*** src/backend/executor/spi.c    14 Aug 2006 22:57:15 -0000    1.157
--- src/backend/executor/spi.c    28 Aug 2006 23:59:42 -0000
***************
*** 920,925 ****
--- 920,926 ----
      PortalDefineQuery(portal,
                        NULL,        /* no statement name */
                        spiplan->query,
+                       NULL,
                        CreateQueryTag(PortalListGetPrimaryQuery(qtlist)),
                        qtlist,
                        ptlist,
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.499
diff -c -c -r1.499 postgres.c
*** src/backend/tcop/postgres.c    15 Aug 2006 18:26:58 -0000    1.499
--- src/backend/tcop/postgres.c    28 Aug 2006 23:59:45 -0000
***************
*** 583,588 ****
--- 583,589 ----
           * For the first EXECUTE we find, record the client statement used by
           * the PREPARE.  PREPARE doesn't save the parse tree so we have no
           * way to conditionally output based on the type of query prepared.
+          * Parse does save the command tag, so perhaps we can use that.
           */
          if (IsA(parsetree, ExecuteStmt))
          {
***************
*** 592,611 ****
              if (*prepare_string == NULL &&
                  (entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
                  entry->query_string)
!             {
!                 *prepare_string = palloc(strlen(entry->query_string) +
!                                       strlen("  [PREPARE:  %s]") - 2 + 1);
!                 sprintf(*prepare_string, "  [PREPARE:  %s]",
!                         entry->query_string);
!             }
          }
      }

      if (log_this_statement)
      {
          ereport(LOG,
!                 (errmsg("statement: %s%s", query_string,
!                         *prepare_string ? *prepare_string : "")));
          return true;
      }
      else
--- 593,608 ----
              if (*prepare_string == NULL &&
                  (entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
                  entry->query_string)
!                 *prepare_string = pstrdup(entry->query_string);
          }
      }

      if (log_this_statement)
      {
          ereport(LOG,
!                 (errmsg("statement: %s", query_string),
!                         *prepare_string ? errdetail("prepare: %s",
!                         *prepare_string) : 0));
          return true;
      }
      else
***************
*** 874,882 ****
      parsetree_list = pg_parse_query(query_string);

      /* Log immediately if dictated by log_statement */
!     if (log_statement != LOGSTMT_NONE)
!         was_logged = log_after_parse(parsetree_list, query_string,
!                                      &prepare_string);

      /*
       * Switch back to transaction context to enter the loop.
--- 871,878 ----
      parsetree_list = pg_parse_query(query_string);

      /* Log immediately if dictated by log_statement */
!     was_logged = log_after_parse(parsetree_list, query_string,
!                                  &prepare_string);

      /*
       * Switch back to transaction context to enter the loop.
***************
*** 957,962 ****
--- 953,959 ----
          PortalDefineQuery(portal,
                            NULL,
                            query_string,
+                           NULL,
                            commandTag,
                            querytree_list,
                            plantree_list,
***************
*** 1097,1106 ****
                                  secs * 1000 + msecs, usecs % 1000)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement: %s%s",
                                  secs * 1000 + msecs, usecs % 1000,
!                                 query_string,
!                                 prepare_string ? prepare_string : "")));
          }
      }

--- 1094,1104 ----
                                  secs * 1000 + msecs, usecs % 1000)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement: %s",
                                  secs * 1000 + msecs, usecs % 1000,
!                                 query_string),
!                                  prepare_string ? errdetail("prepare: %s",
!                                 prepare_string) : 0));
          }
      }

***************
*** 1147,1153 ****

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("prepare %s:  %s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          query_string)));

--- 1145,1151 ----

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: prepare %s, %s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          query_string)));

***************
*** 1384,1391 ****
      /* Switch back to message context */
      MemoryContextSwitchTo(MessageContext);

!     if (log_statement == LOGSTMT_ALL)
!         initStringInfo(&bind_values_str);

      /* Get the fixed part of the message */
      portal_name = pq_getmsgstring(input_message);
--- 1382,1388 ----
      /* Switch back to message context */
      MemoryContextSwitchTo(MessageContext);

!     initStringInfo(&bind_values_str);

      /* Get the fixed part of the message */
      portal_name = pq_getmsgstring(input_message);
***************
*** 1521,1527 ****
              {
                  Oid            typinput;
                  Oid            typioparam;
!                 char       *pstring;

                  getTypeInputInfo(ptype, &typinput, &typioparam);

--- 1518,1524 ----
              {
                  Oid            typinput;
                  Oid            typioparam;
!                 char       *pstring, *p;

                  getTypeInputInfo(ptype, &typinput, &typioparam);

***************
*** 1540,1551 ****
                                           typioparam,
                                           -1);

!                 /* Log the parameter value if needed */
!                 if (log_statement == LOGSTMT_ALL)
!                     appendStringInfo(&bind_values_str, "%s$%d = \"%s\"",
!                                      bind_values_str.len ? ", " : "",
!                                      paramno + 1,
!                                      pstring);

                  /* Free result of encoding conversion, if any */
                  if (pstring && pstring != pbuf.data)
--- 1537,1553 ----
                                           typioparam,
                                           -1);

!                 /* Save the parameter values */
!                 appendStringInfo(&bind_values_str, "%s$%d = '",
!                                  bind_values_str.len ? ", " : "",
!                                  paramno + 1);
!                 for (p = pstring; *p; p++)
!                 {
!                     if (*p == '\'')    /* double single quotes */
!                         appendStringInfoChar(&bind_values_str, *p);
!                     appendStringInfoChar(&bind_values_str, *p);
!                 }
!                 appendStringInfoChar(&bind_values_str, '\'');

                  /* Free result of encoding conversion, if any */
                  if (pstring && pstring != pbuf.data)
***************
*** 1607,1619 ****
      if (log_statement == LOGSTMT_ALL)
      {
          ereport(LOG,
!                 (errmsg("bind %s%s%s:  %s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          *portal->name ? "/" : "",
                          *portal->name ? portal->name : "",
!                         pstmt->query_string ? pstmt->query_string : ""),
!                  bind_values_str.len ? errdetail(bind_values_str.data) : 0));
!         pfree(bind_values_str.data);
      }

      /* Get the result format codes */
--- 1609,1622 ----
      if (log_statement == LOGSTMT_ALL)
      {
          ereport(LOG,
!                 (errmsg("statement: bind %s%s%s%s%s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          *portal->name ? "/" : "",
                          *portal->name ? portal->name : "",
!                         /* print bind parameters if we have them */
!                         bind_values_str.len ? ", " : "",
!                         bind_values_str.len ? bind_values_str.data : ""),
!                         errdetail("prepare: %s", pstmt->query_string)));
      }

      /* Get the result format codes */
***************
*** 1651,1656 ****
--- 1654,1660 ----
      PortalDefineQuery(portal,
                        *stmt_name ? pstrdup(stmt_name) : NULL,
                        pstmt->query_string,
+                       bind_values_str.len ? pstrdup(bind_values_str.data) : NULL,
                        pstmt->commandTag,
                        pstmt->query_list,
                        pstmt->plan_list,
***************
*** 1684,1689 ****
--- 1688,1694 ----
      bool        completed;
      char        completionTag[COMPLETION_TAG_BUFSIZE];
      const char *sourceText = NULL;
+     const char *bindText = NULL;
      const char *prepStmtName;
      bool        save_log_statement_stats = log_statement_stats;
      bool        is_xact_command;
***************
*** 1728,1748 ****
          debug_query_string = "fetch message";
          pgstat_report_activity("<FETCH>");
      }
-     else if (portal->sourceText)
-     {
-         /*
-          * We must copy the sourceText into MessageContext in case the
-          * portal is destroyed during finish_xact_command.  Can avoid
-          * the copy if it's not an xact command, though.
-          */
-         if (is_xact_command)
-             sourceText = pstrdup(portal->sourceText);
-         else
-             sourceText = portal->sourceText;
-
-         debug_query_string = sourceText;
-         pgstat_report_activity(sourceText);
-     }
      else
      {
          debug_query_string = "execute message";
--- 1733,1738 ----
***************
*** 1758,1763 ****
--- 1748,1771 ----
          prepStmtName = "<unnamed>";

      /*
+      * We must copy the sourceText and bindText into MessageContext
+      * in case the portal is destroyed during finish_xact_command.
+      * Can avoid the copy if it's not an xact command, though.
+      */
+     if (is_xact_command)
+         sourceText = pstrdup(portal->sourceText);
+     else
+         sourceText = portal->sourceText;
+
+     if (portal->bindText)
+     {
+         if (is_xact_command)
+             bindText = pstrdup(portal->bindText);
+         else
+             bindText = portal->bindText;
+     }
+
+     /*
       * We use save_log_statement_stats so ShowUsage doesn't report incorrect
       * results because ResetUsage wasn't called.
       */
***************
*** 1766,1777 ****

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("execute %s%s%s%s:  %s",
                          execute_is_fetch ? "fetch from " : "",
                          prepStmtName,
                          *portal_name ? "/" : "",
!                         *portal_name ? portal_name : "",
!                         sourceText ? sourceText : "")));

      BeginCommand(portal->commandTag, dest);

--- 1774,1788 ----

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: execute %s%s%s%s",
                          execute_is_fetch ? "fetch from " : "",
                          prepStmtName,
                          *portal_name ? "/" : "",
!                         *portal_name ? portal_name : ""),
!                         errdetail("prepare: %s%s%s", sourceText,
!                         /* optionally print bind parameters */
!                         bindText ? "  bind: " : "",
!                         bindText ? bindText : "")));

      BeginCommand(portal->commandTag, dest);

***************
*** 1876,1888 ****
                                  secs * 1000 + msecs, usecs % 1000)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  execute %s%s%s%s:  %s",
                                  secs * 1000 + msecs, usecs % 1000,
                                  execute_is_fetch ? "fetch from " : "",
                                  prepStmtName,
                                  *portal_name ? "/" : "",
!                                 *portal_name ? portal_name : "",
!                                 sourceText ? sourceText : "")));
          }
      }

--- 1887,1902 ----
                                  secs * 1000 + msecs, usecs % 1000)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  execute %s%s%s%s",
                                  secs * 1000 + msecs, usecs % 1000,
                                  execute_is_fetch ? "fetch from " : "",
                                  prepStmtName,
                                  *portal_name ? "/" : "",
!                                 *portal_name ? portal_name : ""),
!                                 errdetail("prepare: %s%s%s", sourceText,
!                                 /* optionally print bind parameters */
!                                 bindText ? "  bind: " : "",
!                                 bindText ? bindText : "")));
          }
      }

Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.92
diff -c -c -r1.92 portalmem.c
*** src/backend/utils/mmgr/portalmem.c    14 Aug 2006 22:57:15 -0000    1.92
--- src/backend/utils/mmgr/portalmem.c    28 Aug 2006 23:59:47 -0000
***************
*** 274,279 ****
--- 274,280 ----
  PortalDefineQuery(Portal portal,
                    const char *prepStmtName,
                    const char *sourceText,
+                   const char *bindText,
                    const char *commandTag,
                    List *parseTrees,
                    List *planTrees,
***************
*** 288,293 ****
--- 289,295 ----

      portal->prepStmtName = prepStmtName;
      portal->sourceText = sourceText;
+     portal->bindText = bindText;
      portal->commandTag = commandTag;
      portal->parseTrees = parseTrees;
      portal->planTrees = planTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.66
diff -c -c -r1.66 portal.h
*** src/include/utils/portal.h    14 Aug 2006 22:57:15 -0000    1.66
--- src/include/utils/portal.h    28 Aug 2006 23:59:48 -0000
***************
*** 122,128 ****
       */

      /* The query or queries the portal will execute */
!     const char *sourceText;        /* text of query, if known (may be NULL) */
      const char *commandTag;        /* command tag for original query */
      List       *parseTrees;        /* parse tree(s) */
      List       *planTrees;        /* plan tree(s) */
--- 122,129 ----
       */

      /* The query or queries the portal will execute */
!     const char *sourceText;        /* text of query, if known, might be NULL */
!     const char *bindText;        /* text of bind parameters, might be NULL */
      const char *commandTag;        /* command tag for original query */
      List       *parseTrees;        /* parse tree(s) */
      List       *planTrees;        /* plan tree(s) */
***************
*** 215,220 ****
--- 216,222 ----
  extern void PortalDefineQuery(Portal portal,
                    const char *prepStmtName,
                    const char *sourceText,
+                   const char *bindText,
                    const char *commandTag,
                    List *parseTrees,
                    List *planTrees,