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

Bruce Momjian wrote:
> Tom Lane wrote:
> > Oliver Jowett <oliver@opencloud.com> writes:
> > > A 50-parameter query could be .. interesting ..
> >
> > > I realize that you need this level of output to reflect what is
> > > happening at the protocol level, but seeing all the protocol detail is
> > > not really what you expect when you turn on basic statement logging, is it?
> >
> > Well, we've certainly been beat up often enough about the lack of
> > logging bind parameter values --- I don't think there's any question
> > about the importance of printing them.  I agree that the proposed format
> > is much too verbose though.  In particular, a separate LOG message per
> > parameter is NOT what I had in mind; I want them in DETAIL lines of the
> > bind log message.  (This'd perhaps also address Oliver's issue, since
> > if you didn't want to see the values you could turn down
> > log_error_verbosity.)
>
> OK, I will continue in that direction.  Will post a new patch.

Updated patch attached.  It prints the text bind parameters on a single
detail line.  I still have not seen portal names generated by libpq.

--
  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.71
diff -c -c -r1.71 config.sgml
*** doc/src/sgml/config.sgml    27 Jul 2006 08:30:41 -0000    1.71
--- doc/src/sgml/config.sgml    7 Aug 2006 03:44:47 -0000
***************
*** 2808,2814 ****
          <literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
          and <literal>COPY FROM</>. <literal>PREPARE</> and
          <literal>EXPLAIN ANALYZE</> statements are also logged if their
!         contained command is of an appropriate type.
         </para>
         <para>
          The default is <literal>none</>. Only superusers can change this
--- 2808,2818 ----
          <literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
          and <literal>COPY FROM</>. <literal>PREPARE</> and
          <literal>EXPLAIN ANALYZE</> statements are also logged if their
!         contained command is of an appropriate type.  Protocol-level
!         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
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.48
diff -c -c -r1.48 portalcmds.c
*** src/backend/commands/portalcmds.c    13 Jul 2006 16:49:14 -0000    1.48
--- src/backend/commands/portalcmds.c    7 Aug 2006 03:44:47 -0000
***************
*** 112,117 ****
--- 112,118 ----
       * submitted more than one semicolon delimited queries.
       */
      PortalDefineQuery(portal,
+                       NULL,
                        pstrdup(debug_query_string),
                        "SELECT", /* cursor's query is always a SELECT */
                        list_make1(query),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.58
diff -c -c -r1.58 prepare.c
*** src/backend/commands/prepare.c    14 Jul 2006 14:52:18 -0000    1.58
--- src/backend/commands/prepare.c    7 Aug 2006 03:44:47 -0000
***************
*** 201,206 ****
--- 201,207 ----
      }

      PortalDefineQuery(portal,
+                       NULL,
                        query_string,
                        entry->commandTag,
                        query_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.152
diff -c -c -r1.152 spi.c
*** src/backend/executor/spi.c    14 Jul 2006 14:52:19 -0000    1.152
--- src/backend/executor/spi.c    7 Aug 2006 03:44:48 -0000
***************
*** 919,924 ****
--- 919,925 ----
       * Set up the portal.
       */
      PortalDefineQuery(portal,
+                       NULL,
                        spiplan->query,
                        "SELECT", /* don't have the raw parse tree... */
                        list_make1(queryTree),
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.495
diff -c -c -r1.495 postgres.c
*** src/backend/tcop/postgres.c    6 Aug 2006 02:00:52 -0000    1.495
--- src/backend/tcop/postgres.c    7 Aug 2006 03:44:49 -0000
***************
*** 955,960 ****
--- 955,961 ----
          portal->visible = false;

          PortalDefineQuery(portal,
+                           NULL,
                            query_string,
                            commandTag,
                            querytree_list,
***************
*** 1146,1152 ****

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

--- 1147,1153 ----

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

***************
*** 1367,1372 ****
--- 1368,1374 ----
      PreparedStatement *pstmt;
      Portal        portal;
      ParamListInfo params;
+     StringInfoData str;

      pgstat_report_activity("<BIND>");

***************
*** 1382,1387 ****
--- 1384,1392 ----
      /* Switch back to message context */
      MemoryContextSwitchTo(MessageContext);

+     if (log_statement == LOGSTMT_ALL)
+         initStringInfo(&str);
+
      /* Get the fixed part of the message */
      portal_name = pq_getmsgstring(input_message);
      stmt_name = pq_getmsgstring(input_message);
***************
*** 1450,1462 ****
      else
          portal = CreatePortal(portal_name, false, false);

-     /* We need to output the parameter values someday */
-     if (log_statement == LOGSTMT_ALL)
-         ereport(LOG,
-                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
-                         *portal_name ? portal_name : "<unnamed>",
-                         portal->sourceText ? portal->sourceText : "")));
-
      /*
       * Fetch parameters, if any, and store in the portal's memory context.
       */
--- 1455,1460 ----
***************
*** 1519,1525 ****
              else
                  pformat = 0;    /* default = text */

!             if (pformat == 0)
              {
                  Oid            typinput;
                  Oid            typioparam;
--- 1517,1523 ----
              else
                  pformat = 0;    /* default = text */

!             if (pformat == 0)    /* text mode */
              {
                  Oid            typinput;
                  Oid            typioparam;
***************
*** 1540,1550 ****
                                                                 pstring,
                                                                 typioparam,
                                                                 -1);
                  /* Free result of encoding conversion, if any */
                  if (pstring && pstring != pbuf.data)
                      pfree(pstring);
              }
!             else if (pformat == 1)
              {
                  Oid            typreceive;
                  Oid            typioparam;
--- 1538,1553 ----
                                                                 pstring,
                                                                 typioparam,
                                                                 -1);
+
+                 if (log_statement == LOGSTMT_ALL)
+                     appendStringInfo(&str, "%s$%d = \"%s\"",
+                         *str.data ? ", " : "", paramno + 1, pstring);
+
                  /* Free result of encoding conversion, if any */
                  if (pstring && pstring != pbuf.data)
                      pfree(pstring);
              }
!             else if (pformat == 1)    /* binary mode */
              {
                  Oid            typreceive;
                  Oid            typioparam;
***************
*** 1595,1600 ****
--- 1598,1623 ----
      else
          params = NULL;

+     if (log_statement == LOGSTMT_ALL)
+     {
+         if (*str.data)
+             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 : ""),
+                      errdetail(str.data)));
+         else
+             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 : "")));
+         pfree(str.data);
+     }
+
      /* Get the result format codes */
      numRFormats = pq_getmsgint(input_message, 2);
      if (numRFormats > 0)
***************
*** 1628,1633 ****
--- 1651,1657 ----
       * Define portal and start execution.
       */
      PortalDefineQuery(portal,
+                       *stmt_name ? pstrdup(stmt_name) : NULL,
                        pstmt->query_string,
                        pstmt->commandTag,
                        pstmt->query_list,
***************
*** 1724,1732 ****
      if (log_statement == LOGSTMT_ALL)
          /* We have the portal, so output the source query. */
          ereport(LOG,
!                 (errmsg("statement: <protocol> %sEXECUTE %s  [PREPARE:  %s]",
!                         execute_is_fetch ? "FETCH from " : "",
!                         *portal_name ? portal_name : "<unnamed>",
                          portal->sourceText ? portal->sourceText : "")));

      BeginCommand(portal->commandTag, dest);
--- 1748,1758 ----
      if (log_statement == LOGSTMT_ALL)
          /* We have the portal, so output the source query. */
          ereport(LOG,
!                 (errmsg("execute %s%s%s%s:  %s",
!                         execute_is_fetch ? "fetch from " : "",
!                         portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
!                         *portal->name ? "/" : "",
!                         *portal->name ? portal->name : "",
                          portal->sourceText ? portal->sourceText : "")));

      BeginCommand(portal->commandTag, dest);
***************
*** 1832,1841 ****
                                  secs, msecs)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement: <protocol> %sEXECUTE %s  [PREPARE:  %s]",
                                  secs, msecs,
!                                 execute_is_fetch ? "FETCH from " : "",
!                                 *portal_name ? portal_name : "<unnamed>",
                                  portal->sourceText ? portal->sourceText : "")));
          }
      }
--- 1858,1869 ----
                                  secs, msecs)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  execute %s%s%s%s:  %s",
                                  secs, msecs,
!                                 execute_is_fetch ? "fetch from " : "",
!                                 portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
!                                 *portal->name ? "/" : "",
!                                 *portal->name ? portal->name : "",
                                  portal->sourceText ? portal->sourceText : "")));
          }
      }
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.90
diff -c -c -r1.90 portalmem.c
*** src/backend/utils/mmgr/portalmem.c    14 Jul 2006 14:52:25 -0000    1.90
--- src/backend/utils/mmgr/portalmem.c    7 Aug 2006 03:44:49 -0000
***************
*** 244,249 ****
--- 244,250 ----
   */
  void
  PortalDefineQuery(Portal portal,
+                   const char *prepStmtName,
                    const char *sourceText,
                    const char *commandTag,
                    List *parseTrees,
***************
*** 257,262 ****
--- 258,264 ----

      Assert(commandTag != NULL || parseTrees == NIL);

+     portal->prepStmtName = prepStmtName;
      portal->sourceText = sourceText;
      portal->commandTag = commandTag;
      portal->parseTrees = parseTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.63
diff -c -c -r1.63 portal.h
*** src/include/utils/portal.h    13 Jul 2006 18:01:02 -0000    1.63
--- src/include/utils/portal.h    7 Aug 2006 03:44:50 -0000
***************
*** 100,105 ****
--- 100,106 ----
  {
      /* Bookkeeping data */
      const char *name;            /* portal's name */
+     const char *prepStmtName;    /* protocol prepare name */
      MemoryContext heap;            /* subsidiary memory for portal */
      ResourceOwner resowner;        /* resources owned by portal */
      void        (*cleanup) (Portal portal);        /* cleanup hook */
***************
*** 202,207 ****
--- 203,209 ----
  extern void DropDependentPortals(MemoryContext queryContext);
  extern Portal GetPortalByName(const char *name);
  extern void PortalDefineQuery(Portal portal,
+                   const char *prepStmtName,
                    const char *sourceText,
                    const char *commandTag,
                    List *parseTrees,