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

OK, updated patch, with output of text bind parameters.  New output is:

    LOG:  prepare sel1:  SELECT $1 + $2;
    LOG:  bind sel1:  SELECT $1 + $2;
    LOG:  bind sel1:  parameter 1:  "8"
    LOG:  bind sel1:  parameter 2:  "5"
    LOG:  execute sel1:  SELECT $1 + $2;

I put each bind parameter on a separate line.  Is that OK?

I also updated the documentation.  Test program also attached.

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <bruce@momjian.us> writes:
> > > I modified the code to store the user statement name in the portal for
> > > protocol execute, so I can print the user name at that time.
> >
> > Please forget that and print the portal name.  I'm getting tired of
> > repeating it, but: there are two different names here and they are
> > both important.  The bind message should print both names.
>
> OK, I added code to print an optional "/" and the portal name.  However,
> I can't get libpq to show a portal name.  Looking at libpq, does it only
> use "" portals, because the only place I see it sending a "B" shows a ""
> portal name?  How can I test a portal name display?
>
> > > Here is
> > > the new output:
> >
> > >     LOG:  statement protocol prepare sel1:  SELECT 1;
> > >     LOG:  statement protocol bind sel1:  SELECT 1;
> > >     LOG:  statement protocol execute sel1:  SELECT 1;
> >
> > If we could lose the noise words "statement protocol" we'd be getting
> > somewhere ...
>
> OK, as no one has said they like "statement protocol", the new output is:
>
>     LOG:  prepare sel1:  SELECT 1;
>     LOG:  bind sel1:  SELECT 1;
>     LOG:  execute sel1:  SELECT 1;
>
> I will take a look at printing out bind text parameters.
>
> --
>   Bruce Momjian   bruce@momjian.us
>   EnterpriseDB    http://www.enterprisedb.com
>
>   + If your life is a hard drive, Christ can be your backup. +


>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
>        choose an index scan if your joining column's datatypes do not
>        match

--
  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    5 Aug 2006 04:55:50 -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    5 Aug 2006 04:55:50 -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    5 Aug 2006 04:55:51 -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    5 Aug 2006 04:55:51 -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.494
diff -c -c -r1.494 postgres.c
*** src/backend/tcop/postgres.c    4 Aug 2006 18:53:46 -0000    1.494
--- src/backend/tcop/postgres.c    5 Aug 2006 04:55:52 -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)));

***************
*** 1452,1460 ****
      /* 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.
--- 1453,1463 ----
      /* We need to output the parameter values someday */
      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 : "")));

      /*
       * Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1517,1523 ****
              else
                  pformat = 0;    /* default = text */

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

!             if (pformat == 0)    /* text mode */
              {
                  Oid            typinput;
                  Oid            typioparam;
***************
*** 1538,1548 ****
                                                                 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;
--- 1541,1559 ----
                                                                 pstring,
                                                                 typioparam,
                                                                 -1);
+
+                 if (log_statement == LOGSTMT_ALL)
+                     ereport(LOG,
+                             (errmsg("bind %s%s%s:  parameter %d:  \"%s\"",
+                                     *stmt_name ? stmt_name : "<unnamed>",
+                                     *portal->name ? "/" : "",
+                                     *portal->name ? portal->name : "", i + 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;
***************
*** 1624,1629 ****
--- 1635,1641 ----
       * Define portal and start execution.
       */
      PortalDefineQuery(portal,
+                       *stmt_name ? pstrdup(stmt_name) : NULL,
                        pstmt->query_string,
                        pstmt->commandTag,
                        pstmt->query_list,
***************
*** 1720,1728 ****
      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);
--- 1732,1742 ----
      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);
***************
*** 1828,1837 ****
                                  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 : "")));
          }
      }
--- 1842,1853 ----
                                  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    5 Aug 2006 04:55:53 -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    5 Aug 2006 04:55:54 -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,
/*
 * testlibpq.c
 *
 *      Test the C version of libpq, the PostgreSQL frontend library.
 */
#include <stdio.h>
#include <stdlib.h>
#include "libpq-fe.h"

static void
exit_nicely(PGconn *conn)
{
    PQfinish(conn);
    exit(1);
}

int
main(int argc, char **argv)
{
    const char *conninfo;
    PGconn       *conn;
    PGresult   *res;
    int            nFields;
    int            i,
                j;
    const char        *val[2];
    int            types[2];


    /*
     * If the user supplies a parameter on the command line, use it as the
     * conninfo string; otherwise default to setting dbname=postgres and using
     * environment variables or defaults for all other connection parameters.
     */
    if (argc > 1)
        conninfo = argv[1];
    else
        conninfo = "dbname = postgres";

    /* Make a connection to the database */
    conn = PQconnectdb(conninfo);

    /* Check to see that the backend connection was successfully made */
    if (PQstatus(conn) != CONNECTION_OK)
    {
        fprintf(stderr, "Connection to database failed: %s",
                PQerrorMessage(conn));
        exit_nicely(conn);
    }

    res = PQexec(conn, "SET log_statement = 'all';");
    if (PQresultStatus(res) != PGRES_COMMAND_OK)
    {
        fprintf(stderr, "BEGIN command failed: %s", PQerrorMessage(conn));
        PQclear(res);
        exit_nicely(conn);
    }

    /*
     * Should PQclear PGresult whenever it is no longer needed to avoid memory
     * leaks
     */
    PQclear(res);

    /*
     * Our test case here involves using a cursor, for which we must be inside
     * a transaction block.  We could do the whole thing with a single
     * PQexec() of "select * from pg_database", but that's too trivial to make
     * a good example.
     */

    /*
     * Fetch rows from pg_database, the system catalog of databases
     */
    types[0] = 23;
    types[1] = 23;
    res = PQprepare(conn, "sel1", "SELECT $1 + $2;", 2, types);
    if (PQresultStatus(res) != PGRES_COMMAND_OK)
    {
        fprintf(stderr, "prepared failed: %s", PQerrorMessage(conn));
        PQclear(res);
        exit_nicely(conn);
    }
    PQclear(res);

    val[0] = "8";
    val[1] = "5";
    res = PQexecPrepared(conn, "sel1", 2, val, NULL, NULL, 0);
    if (PQresultStatus(res) != PGRES_TUPLES_OK)
    {
        fprintf(stderr, "exec failed: %s", PQerrorMessage(conn));
        PQclear(res);
        exit_nicely(conn);
    }

    /* first, print out the attribute names */
    nFields = PQnfields(res);
    for (i = 0; i < nFields; i++)
        printf("%-15s", PQfname(res, i));
    printf("\n\n");

    /* next, print out the rows */
    for (i = 0; i < PQntuples(res); i++)
    {
        for (j = 0; j < nFields; j++)
            printf("%-15s", PQgetvalue(res, i, j));
        printf("\n");
    }

    PQclear(res);

    /* close the connection to the database and cleanup */
    PQfinish(conn);

    return 0;
}