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)
---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]

Reply via email to