Re: Exec statement logging - Mailing list pgsql-patches

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.

--
  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    16 May 2005 22:36:58 -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 22:37:00 -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,527 ----
      List       *raw_parsetree_list;
      ListCell   *parsetree_item;

+     /* reset prepare_string */
+     if (prepare_string != NULL)
+         free(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)
+                     {
+                         /* must use malloc() so it can be unconditionally freed */
+                         prepare_string = malloc(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");
--- 531,566 ----
                    ((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.
       */
--- 775,782 ----
      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 ****
--- 832,841 ----
       */
      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)
--- 1069,1080 ----
              (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)