Re: Exec statement logging

OK, new patch.  I used portal->sourceText as Tom suggested, and checked
for NULL before printing.  I put the original query in brackets in the
log output, patch attached.

I would like to also do this for server-side EXECUTE.  I am have
attached a second version that does it by using the existing loop we use
to check for a match for log_statement patterns.  The code checks for an
ExecuteStmt node, and saves the prepare string that matches the portal.
The system can't determine the actual prepare string, so I used the
debug_query_string for a server-side PREPARE --- previously it just had
a null for the prepare string.  Also, rather than change the API for
pg_parse_query(), I use a global variable that I check after the
function call.  Here is sample output with log_statement and
log_min_duration_statement enabled:

    PREPARE xx AS SELECT 1;
    LOG:  statement: PREPARE xx AS SELECT 1;
    LOG:  duration: 1.102 ms  statement: PREPARE xx AS SELECT 1;
    PREPARE

    EXECUTE xx;
    LOG:  statement: EXECUTE xx;  [client PREPARE:  PREPARE xx AS SELECT 1;]
    LOG:  duration: 0.990 ms  statement: EXECUTE xx;  [client PREPARE:  PREPARE xx AS SELECT 1;]
     ?column?
    ----------
            1
    (1 row)

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

Simon Riggs wrote:
> On Sat, 2005-05-14 at 16:55 -0400, Bruce Momjian wrote:
> > Uh, I am confused by this.  Your code test is:
> >
> > +       if ((log_statement == LOGSTMT_ALL && save_log_duration) ||
> > +             save_log_min_duration_statement)
> > +               gettimeofday(&start_t, NULL);
> >
> > First, log_min_duration_statement == -1 turns off logging.  Your test
> > would enable it for -1.  Also, you added "log_statement == LOGSTMT_ALL",
> > but don't have a similar test lower down where gettimeofday is used, so
> > I don't understand its usage here, or why it would be used in this
> > place.  The original test is:
> >
> > +       if (save_log_duration || save_log_min_duration_statement != -1)
> > +           gettimeofday(&start_t, NULL);
>
> Yes, that looks wrong. Thanks for your diligence. I'm sorry that you've
> had to both spot an error and recode for it, I was expecting to do that.
>
> > One thing you did was to log debug_query_string, but I don't see how
> > that could be the right value.  I assume it would be empty in a
> > client-side execute, or be the previous query.  I instead used "EXECUTE
> > portal_name" because that is what we are passed from the client.
>
> I used the debug_query_string because even in the EXEC case it is set,
> so that the SQL statement appears correctly in pg_stat_activity. It may
> look wrong, but it is there.
>
> That part, at least, is correct, since I have used the patch in tuning.
>
> Perhaps it is only there when stats_command_string is set?
>
> Setting the SQL string to be only EXECUTE portal_name makes the log
> output almost useless for query tuning, so please reconsider that.
> Perhaps you could include both the portal name and the SQL statement?
>
> Best Regards, Simon Riggs
>

--
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c    21 Apr 2005 19:18:13 -0000    1.443
--- src/backend/tcop/postgres.c    16 May 2005 03:40:00 -0000
***************
*** 1011,1017 ****
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);

          /* Only print duration if we previously printed the statement. */
          if (statement_logged && save_log_duration)
--- 1011,1018 ----
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
!                 (long) (stop_t.tv_usec - start_t.tv_usec);

          /* Only print duration if we previously printed the statement. */
          if (statement_logged && save_log_duration)
***************
*** 1579,1584 ****
--- 1580,1590 ----
      bool        is_trans_exit = false;
      bool        completed;
      char        completionTag[COMPLETION_TAG_BUFSIZE];
+     struct timeval start_t,
+                 stop_t;
+     bool        save_log_duration = log_duration;
+     int            save_log_min_duration_statement = log_min_duration_statement;
+     bool        save_log_statement_stats = log_statement_stats;

      /* Adjust destination to tell printtup.c what to do */
      dest = whereToSendOutput;
***************
*** 1615,1620 ****
--- 1621,1648 ----

      set_ps_display(portal->commandTag);

+     /*
+      * We use save_log_* so "SET log_duration = true"  and "SET
+      * log_min_duration_statement = true" don't report incorrect time
+      * because gettimeofday() wasn't called. Similarly,
+      * log_statement_stats has to be captured once.
+      */
+     if (save_log_duration || save_log_min_duration_statement != -1)
+         gettimeofday(&start_t, NULL);
+
+     if (save_log_statement_stats)
+         ResetUsage();
+
+     statement_logged = false;
+     if (log_statement == LOGSTMT_ALL)
+     {
+         /* We have the portal, so output the source query. */
+         ereport(LOG,
+                 (errmsg("statement: EXECUTE %s  [PREPARE:  %s]", portal_name,
+                         portal->sourceText ? portal->sourceText : "")));
+         statement_logged = true;
+     }
+
      BeginCommand(portal->commandTag, dest);

      /* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1737,1786 ----
              pq_putemptymessage('s');
      }

+     /*
+      * Combine processing here as we need to calculate the query duration
+      * in both instances.
+      */
+     if (save_log_duration || save_log_min_duration_statement != -1)
+     {
+         long        usecs;
+
+         gettimeofday(&stop_t, NULL);
+         if (stop_t.tv_usec < start_t.tv_usec)
+         {
+             stop_t.tv_sec--;
+             stop_t.tv_usec += 1000000;
+         }
+         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
+                 (long) (stop_t.tv_usec - start_t.tv_usec);
+
+         /* Only print duration if we previously printed the statement. */
+         if (statement_logged && save_log_duration)
+             ereport(LOG,
+                     (errmsg("duration: %ld.%03ld ms",
+                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
+                      (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+
+         /*
+          * Output a duration_statement to the log if the query has
+          * exceeded the min duration, or if we are to print all durations.
+          */
+         if (save_log_min_duration_statement == 0 ||
+             (save_log_min_duration_statement > 0 &&
+              usecs >= save_log_min_duration_statement * 1000))
+             ereport(LOG,
+                     (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s  [PREPARE:  %s]",
+                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
+                         (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
+                             portal_name,
+                             portal->sourceText ? portal->sourceText : "")));
+     }
+
+     if (save_log_statement_stats)
+         ShowUsage("QUERY STATISTICS");
+
      debug_query_string = NULL;
  }

Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.36
diff -c -c -r1.36 prepare.c
*** src/backend/commands/prepare.c    1 Jan 2005 05:43:06 -0000    1.36
--- src/backend/commands/prepare.c    16 May 2005 18:00:52 -0000
***************
*** 104,112 ****
      /* Generate plans for queries.    Snapshot is already set. */
      plan_list = pg_plan_queries(query_list, NULL, false);

!     /* Save the results. */
      StorePreparedStatement(stmt->name,
!                            NULL,    /* text form not available */
                             commandTag,
                             query_list,
                             plan_list,
--- 104,115 ----
      /* Generate plans for queries.    Snapshot is already set. */
      plan_list = pg_plan_queries(query_list, NULL, false);

!     /*
!      *    Save the results.  We don't have the query string for this PREPARE,
!      *    but we do have the string we got from the client, so use that.
!      */
      StorePreparedStatement(stmt->name,
!                            debug_query_string,
                             commandTag,
                             query_list,
                             plan_list,
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c    21 Apr 2005 19:18:13 -0000    1.443
--- src/backend/tcop/postgres.c    16 May 2005 18:00:54 -0000
***************
*** 73,78 ****
--- 73,79 ----
   */
  const char *debug_query_string; /* for pgmonitor and
                                   * log_min_error_statement */
+ char *prepare_string = NULL;        /* used for passing PREPARE source string */

  /* Note: whereToSendOutput is initialized for the bootstrap/standalone case */
  CommandDest whereToSendOutput = Debug;
***************
*** 467,504 ****
      List       *raw_parsetree_list;
      ListCell   *parsetree_item;

      statement_logged = false;
-     if (log_statement == LOGSTMT_ALL)
-     {
-         ereport(LOG,
-                 (errmsg("statement: %s", query_string)));
-         statement_logged = true;
-     }

      if (log_parser_stats)
          ResetUsage();

      raw_parsetree_list = raw_parser(query_string);

!     /* do log_statement tests for mod and ddl */
!     if (log_statement == LOGSTMT_MOD ||
          log_statement == LOGSTMT_DDL)
      {
          foreach(parsetree_item, raw_parsetree_list)
          {
              Node       *parsetree = (Node *) lfirst(parsetree_item);
              const char *commandTag;
!
              if (IsA(parsetree, ExplainStmt) &&
                  ((ExplainStmt *) parsetree)->analyze)
                  parsetree = (Node *) (((ExplainStmt *) parsetree)->query);
!
              if (IsA(parsetree, PrepareStmt))
                  parsetree = (Node *) (((PrepareStmt *) parsetree)->query);
!
              if (IsA(parsetree, SelectStmt))
                  continue;        /* optimization for frequent command */

              if (log_statement == LOGSTMT_MOD &&
                  (IsA(parsetree, InsertStmt) ||
                   IsA(parsetree, UpdateStmt) ||
--- 468,526 ----
      List       *raw_parsetree_list;
      ListCell   *parsetree_item;

+     /* reset prepare_string */
+     if (prepare_string != NULL)
+         pfree(prepare_string);
+     prepare_string = NULL;
+
      statement_logged = false;

      if (log_parser_stats)
          ResetUsage();

      raw_parsetree_list = raw_parser(query_string);

!     if (log_statement == LOGSTMT_ALL ||
!         log_statement == LOGSTMT_MOD ||
          log_statement == LOGSTMT_DDL)
      {
          foreach(parsetree_item, raw_parsetree_list)
          {
              Node       *parsetree = (Node *) lfirst(parsetree_item);
              const char *commandTag;
!
              if (IsA(parsetree, ExplainStmt) &&
                  ((ExplainStmt *) parsetree)->analyze)
                  parsetree = (Node *) (((ExplainStmt *) parsetree)->query);
!
              if (IsA(parsetree, PrepareStmt))
                  parsetree = (Node *) (((PrepareStmt *) parsetree)->query);
!
              if (IsA(parsetree, SelectStmt))
                  continue;        /* optimization for frequent command */
+
+             if (IsA(parsetree, ExecuteStmt))
+             {
+                 ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
+                 PreparedStatement *entry;

+                 /*
+                  *    For the first EXECUTE we find before printing the
+                  *    statement string, find the client statement that
+                  *    generated the PREPARE.
+                  */
+                 if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL)
+                 {
+                     if (prepare_string == NULL && entry->query_string)
+                     {
+                         prepare_string = palloc(strlen(entry->query_string) +
+                                       strlen("  [client PREPARE:  %s]") - 1);
+                         sprintf(prepare_string, "  [client PREPARE:  %s]",
+                                       entry->query_string);
+                     }
+                 }
+             }
+
              if (log_statement == LOGSTMT_MOD &&
                  (IsA(parsetree, InsertStmt) ||
                   IsA(parsetree, UpdateStmt) ||
***************
*** 508,531 ****
                    ((CopyStmt *) parsetree)->is_from)))    /* COPY FROM */
              {
                  ereport(LOG,
!                         (errmsg("statement: %s", query_string)));
                  statement_logged = true;
                  break;
              }
              commandTag = CreateCommandTag(parsetree);
!             if (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
!                 strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
!                 strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
!                 IsA(parsetree, GrantStmt) ||    /* GRANT or REVOKE */
!                 IsA(parsetree, CommentStmt))
              {
                  ereport(LOG,
!                         (errmsg("statement: %s", query_string)));
                  statement_logged = true;
                  break;
              }
          }
      }

      if (log_parser_stats)
          ShowUsage("PARSER STATISTICS");
--- 530,565 ----
                    ((CopyStmt *) parsetree)->is_from)))    /* COPY FROM */
              {
                  ereport(LOG,
!                         (errmsg("statement: %s%s", query_string,
!                                 prepare_string ? prepare_string : "")));
                  statement_logged = true;
                  break;
              }
              commandTag = CreateCommandTag(parsetree);
!             if ((log_statement == LOGSTMT_MOD ||
!                  log_statement == LOGSTMT_DDL) &&
!                 (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
!                  strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
!                  strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
!                  IsA(parsetree, GrantStmt) ||    /* GRANT or REVOKE */
!                  IsA(parsetree, CommentStmt)))
              {
                  ereport(LOG,
!                         (errmsg("statement: %s%s", query_string,
!                                 prepare_string ? prepare_string : "")));
                  statement_logged = true;
                  break;
              }
          }
      }
+
+     if (log_statement == LOGSTMT_ALL)
+     {
+         ereport(LOG,
+                 (errmsg("statement: %s%s", query_string,
+                                 prepare_string ? prepare_string : "")));
+         statement_logged = true;
+     }

      if (log_parser_stats)
          ShowUsage("PARSER STATISTICS");
***************
*** 740,746 ****
      bool        save_log_duration = log_duration;
      int            save_log_min_duration_statement = log_min_duration_statement;
      bool        save_log_statement_stats = log_statement_stats;
!
      /*
       * Report query to various monitoring facilities.
       */
--- 774,781 ----
      bool        save_log_duration = log_duration;
      int            save_log_min_duration_statement = log_min_duration_statement;
      bool        save_log_statement_stats = log_statement_stats;
!     char       *my_prepare_string = NULL;
!
      /*
       * Report query to various monitoring facilities.
       */
***************
*** 796,801 ****
--- 831,840 ----
       */
      parsetree_list = pg_parse_query(query_string);

+     /* If EXECUTE generated a PREPARE source, record it for later */
+     if (prepare_string != NULL)
+         my_prepare_string = pstrdup(prepare_string);
+
      /*
       * Switch back to transaction context to enter the loop.
       */
***************
*** 1029,1039 ****
              (save_log_min_duration_statement > 0 &&
               usecs >= save_log_min_duration_statement * 1000))
              ereport(LOG,
!                     (errmsg("duration: %ld.%03ld ms  statement: %s",
                          (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
                                (stop_t.tv_usec - start_t.tv_usec) / 1000),
                          (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
!                             query_string)));
      }

      if (save_log_statement_stats)
--- 1068,1079 ----
              (save_log_min_duration_statement > 0 &&
               usecs >= save_log_min_duration_statement * 1000))
              ereport(LOG,
!                     (errmsg("duration: %ld.%03ld ms  statement: %s%s",
                          (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
                                (stop_t.tv_usec - start_t.tv_usec) / 1000),
                          (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
!                             query_string,
!                             prepare_string ? prepare_string : "")));
      }

      if (save_log_statement_stats)