log_statement output for protocol prepare/bind/execute - Mailing list pgsql-patches

Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > !                 (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> > --- 1452,1460 ----
> > !                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
> > !                         *portal_name ? portal_name : "<unnamed>",
> > !                         portal->sourceText ? portal->sourceText : "")));
>
> This is getting less readable not more so; and you still haven't got the
> prepared statement's name in there, let alone any place to put the
> parameter values.
>
> Perhaps we should give up on the idea that this can all fit on one log
> line?  Maybe
>
>     LOG:  parse: <statement-name>
>     DETAIL:  statement: <source-text>
>
>     LOG:  bind: <portal-name> to <statement-name>
>     DETAIL:  statement: <source-text>
>     parameter 1: <parameter value>
>     parameter 2: <parameter value>
>     ...
>
>     LOG:  execute: <portal-name>
>     DETAIL:  statement: <source-text>
>
> The $64 question here is whether we want to repeat the source-text
> in all three messages (parse, bind, execute) or try to reduce the
> verbosity.

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.  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;

Patch attached.  I am also attaching my test program.  Should I put that
in CVS somewhere?  Libpq.sgml.

I had to pstrdup() the statement name.  Is that OK?

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

  + If your life is a hard drive, Christ can be your backup. +
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    4 Aug 2006 22:22:19 -0000
***************
*** 112,117 ****
--- 112,118 ----
       * submitted more than one semicolon delimited queries.
       */
      PortalDefineQuery(portal,
+                       "",
                        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    4 Aug 2006 22:22:19 -0000
***************
*** 201,206 ****
--- 201,207 ----
      }

      PortalDefineQuery(portal,
+                       "",
                        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    4 Aug 2006 22:22:19 -0000
***************
*** 919,924 ****
--- 919,925 ----
       * Set up the portal.
       */
      PortalDefineQuery(portal,
+                       "",
                        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    4 Aug 2006 22:22:21 -0000
***************
*** 955,960 ****
--- 955,961 ----
          portal->visible = false;

          PortalDefineQuery(portal,
+                           "",
                            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("statement protocol 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,1461 ----
      /* We need to output the parameter values someday */
      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement protocol bind %s:  %s",
!                         *stmt_name ? stmt_name : "<unnamed>",
!                         pstmt->query_string ? pstmt->query_string : "")));

      /*
       * Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1624,1629 ****
--- 1625,1631 ----
       * Define portal and start execution.
       */
      PortalDefineQuery(portal,
+                       pstrdup(stmt_name),
                        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);
--- 1722,1730 ----
      if (log_statement == LOGSTMT_ALL)
          /* We have the portal, so output the source query. */
          ereport(LOG,
!                 (errmsg("statement protocol execute %s%s:  %s",
!                         execute_is_fetch ? "fetch from " : "",
!                         *portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
                          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 : "")));
          }
      }
--- 1830,1839 ----
                                  secs, msecs)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement protocol execute %s%s:  %s",
                                  secs, msecs,
!                                 execute_is_fetch ? "fetch from " : "",
!                                 *portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
                                  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    4 Aug 2006 22:22:21 -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 = pstrdup(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    4 Aug 2006 22:22:22 -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;

    /*
     * 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
     */
    res = PQprepare(conn, "sel1", "SELECT 1;", 0, NULL);
    if (PQresultStatus(res) != PGRES_COMMAND_OK)
    {
        fprintf(stderr, "prepared failed: %s", PQerrorMessage(conn));
        PQclear(res);
        exit_nicely(conn);
    }
    PQclear(res);

    res = PQexecPrepared(conn, "sel1", 0, NULL, 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;
}