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;
  }
  
---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
    (send "unregister YourEmailAddressHere" to [EMAIL PROTECTED])

Reply via email to