Re: Exec statement logging - Mailing list pgsql-patches

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > 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.
> >
> > This is horribly ugly and will doubtless lead to pfree crashes.  What
>
> Agreed, it needs work.  I modified the patch to use malloc/free so that
> you can always free the memory at the top of the function.
>
> > was the point again?
>
> Simon said that the EXECUTE is pretty useless for debugging unless we
> show the prepare query.  His patch shows the prepare query for
> client-side prepare, but not for server side when using the
> PREPARE/EXECUTE commands --- seems we should display it in both cases.

Here is an updated version of the patch.  It pulls post-parse logging
out into a separate function, called log_after_parse(), so we only log
in places we want it.  I added code to log client-side parse, and
prepare, were appropriate, and have the logging of client-side and
server-side execute with the PREPARE string.

--
  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/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    20 May 2005 14:15:12 -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    20 May 2005 14:15:17 -0000
***************
*** 82,90 ****

  LogStmtLevel log_statement = LOGSTMT_NONE;

- /* flag indicating if the statement satisfies log_statement */
- bool        statement_logged;
-
  /* GUC variable for maximum stack depth (measured in kilobytes) */
  int            max_stack_depth = 2048;

--- 82,87 ----
***************
*** 152,157 ****
--- 149,156 ----
  static int    InteractiveBackend(StringInfo inBuf);
  static int    SocketBackend(StringInfo inBuf);
  static int    ReadCommand(StringInfo inBuf);
+ static bool log_after_parse(List *raw_parsetree_list,
+                 const char *query_string, char **prepare_string);
  static void start_xact_command(void);
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
***************
*** 465,538 ****
  pg_parse_query(const char *query_string)
  {
      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) ||
-                  IsA(parsetree, DeleteStmt) ||
-                  IsA(parsetree, TruncateStmt) ||
-                  (IsA(parsetree, CopyStmt) &&
-                   ((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");

      return raw_parsetree_list;
  }

  /*
   * Given a raw parsetree (gram.y output), and optionally information about
   * types of parameter symbols ($n), perform parse analysis and rule rewriting.
--- 464,557 ----
  pg_parse_query(const char *query_string)
  {
      List       *raw_parsetree_list;

      if (log_parser_stats)
          ResetUsage();

      raw_parsetree_list = raw_parser(query_string);

      if (log_parser_stats)
          ShowUsage("PARSER STATISTICS");

      return raw_parsetree_list;
  }

+ static bool
+ log_after_parse(List *raw_parsetree_list, const char *query_string,
+                    char **prepare_string)
+ {
+     ListCell   *parsetree_item;
+     bool        log_this_statement = (log_statement == LOGSTMT_ALL);
+
+     *prepare_string = NULL;
+
+     /*    Check if we need to log the statement, and get prepare_string. */
+     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) ||
+              IsA(parsetree, DeleteStmt) ||
+              IsA(parsetree, TruncateStmt) ||
+              (IsA(parsetree, CopyStmt) &&
+               ((CopyStmt *) parsetree)->is_from)))    /* COPY FROM */
+             log_this_statement = true;
+
+         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)))
+             log_this_statement = true;
+
+         /*
+          *    For the first EXECUTE we find, record the client statement
+          *    used by the PREPARE.
+          */
+         if (IsA(parsetree, ExecuteStmt))
+         {
+             ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
+             PreparedStatement *entry;
+
+             if ((entry = FetchPreparedStatement(stmt->name, false)) != 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_this_statement)
+     {
+         ereport(LOG,
+                 (errmsg("statement: %s%s", query_string,
+                         *prepare_string ? *prepare_string : "")));
+         return true;
+     }
+     else
+         return false;
+ }
+
+
  /*
   * Given a raw parsetree (gram.y output), and optionally information about
   * types of parameter symbols ($n), perform parse analysis and rule rewriting.
***************
*** 735,746 ****
      MemoryContext oldcontext;
      List       *parsetree_list;
      ListCell   *parsetree_item;
!     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;
!
      /*
       * Report query to various monitoring facilities.
       */
--- 754,766 ----
      MemoryContext oldcontext;
      List       *parsetree_list;
      ListCell   *parsetree_item;
!     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;
!     char        *prepare_string = NULL;
!     bool        was_logged = false;
!
      /*
       * Report query to various monitoring facilities.
       */
***************
*** 796,801 ****
--- 816,825 ----
       */
      parsetree_list = pg_parse_query(query_string);

+     if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1)
+         was_logged = log_after_parse(parsetree_list, query_string,
+                                         &prepare_string);
+
      /*
       * Switch back to transaction context to enter the loop.
       */
***************
*** 1011,1020 ****
              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 +
--- 1035,1045 ----
              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 (was_logged && save_log_duration)
              ereport(LOG,
                      (errmsg("duration: %ld.%03ld ms",
                          (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
***************
*** 1029,1044 ****
              (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)
          ShowUsage("QUERY STATISTICS");

      debug_query_string = NULL;
  }

--- 1054,1073 ----
              (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)
          ShowUsage("QUERY STATISTICS");

+     if (prepare_string != NULL)
+         pfree(prepare_string);
+
      debug_query_string = NULL;
  }

***************
*** 1074,1079 ****
--- 1103,1112 ----
      if (save_log_statement_stats)
          ResetUsage();

+     if (log_statement == LOGSTMT_ALL)
+         ereport(LOG,
+                 (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string)));
+
      /*
       * Start up a transaction command so we can run parse analysis etc.
       * (Note that this will normally change current memory context.)
***************
*** 1371,1376 ****
--- 1404,1413 ----
      else
          portal = CreatePortal(portal_name, false, false);

+     if (log_statement == LOGSTMT_ALL)
+         ereport(LOG,
+                 (errmsg("statement: <BIND> %s", portal_name)));
+
      /*
       * Fetch parameters, if any, and store in the portal's memory context.
       *
***************
*** 1579,1584 ****
--- 1616,1625 ----
      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 ****
--- 1656,1679 ----

      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();
+
+     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 : "")));
+
      BeginCommand(portal->commandTag, dest);

      /* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1768,1817 ----
              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 (log_statement == LOGSTMT_ALL && 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;
  }