Tweak the behavior of log_duration as proposed by Guillaume Smet: rather

than being equivalent to setting log_min_duration_statement to zero, this
option now forces logging of all query durations, but doesn't force logging
of query text.  Also, add duration logging coverage for fastpath function
calls.

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 669110a5fda4517431a95e93046964cf6a71b40b..2dcde4c14d1e87811237e567c5af61bf501b14cf 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -1,4 +1,4 @@
-
+
 
 
   Server Configuration
@@ -2718,23 +2718,22 @@ SELECT * FROM parent WHERE key = 2400;
         Only superusers can change this setting.
        
 
-        
-         For clients using extended query protocol, durations of the Parse,
-         Bind, and Execute steps are logged independently.
-        
+       
+        For clients using extended query protocol, durations of the Parse,
+        Bind, and Execute steps are logged independently.
+       
 
        
         
-         When using this option together with
-         ,
-         the text of statements that are logged because of
-         log_statement will not be repeated in the
-         duration log message.
-         If you are not using syslog, it is recommended 
-         that you log the PID or session ID using
-         
-         so that you can link the statement message to the later
-         duration message using the process ID or session ID.
+         The difference between setting this option and setting
+          to zero is that
+         exceeding log_min_duration_statement forces the text of
+         the query to be logged, but this option doesn't.  Thus, if
+         log_duration is on and
+         log_min_duration_statement has a positive value, all
+         durations are logged but the query text is included only for
+         statements exceeding the threshold.  This behavior can be useful for
+         gathering statistics in high-load installations.
         
        
       

diff --git a/src/backend/tcop/fastpath.c b/src/backend/tcop/fastpath.c
index a031a212cca1829fa5050ad93be5c59d76c974a6..26931e0a6d791d3016a634f8ecde5fb76402297e 100644 (file)
--- a/src/backend/tcop/fastpath.c
+++ b/src/backend/tcop/fastpath.c
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.91 2006/07/14 14:52:23 momjian Exp $
+ *   $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.92 2006/09/08 15:55:53 tgl Exp $
  *
  * NOTES
  *   This cruft is the server side of PQfn.
@@ -274,6 +274,8 @@ HandleFunctionRequest(StringInfo msgBuf)
    struct fp_info my_fp;
    struct fp_info *fip;
    bool        callit;
+   bool        was_logged = false;
+   char        msec_str[32];
 
    /*
     * Read message contents if not already done.
@@ -314,10 +316,14 @@ HandleFunctionRequest(StringInfo msgBuf)
 
    fid = (Oid) pq_getmsgint(msgBuf, 4);        /* function oid */
 
+   /* Log as soon as we have the function OID */
    if (log_statement == LOGSTMT_ALL)
+   {
        ereport(LOG,
                (errmsg("fastpath function call: function OID %u",
                        fid)));
+       was_logged = true;
+   }
 
    /*
     * There used to be a lame attempt at caching lookup info here. Now we
@@ -387,6 +393,22 @@ HandleFunctionRequest(StringInfo msgBuf)
 
    SendFunctionResult(retval, fcinfo.isnull, fip->rettype, rformat);
 
+   /*
+    * Emit duration logging if appropriate.
+    */
+   switch (check_log_duration(msec_str, was_logged))
+   {
+       case 1:
+           ereport(LOG,
+                   (errmsg("duration: %s ms", msec_str)));
+           break;
+       case 2:
+           ereport(LOG,
+                   (errmsg("duration: %s ms  fastpath function call: function OID %u",
+                           msec_str, fid)));
+           break;
+   }
+
    return 0;
 }
 

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 30c722f4adb4d6e92b88dc5030d858e3626924e1..0344eec53fcf41568d1f716a3065093adea40320 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.507 2006/09/07 22:52:01 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.508 2006/09/08 15:55:53 tgl Exp $
  *
  * NOTES
  *   this is the "main" module of the postgres backend and
@@ -159,7 +159,6 @@ static int  ReadCommand(StringInfo inBuf);
 static List *pg_rewrite_queries(List *querytree_list);
 static bool check_log_statement_raw(List *raw_parsetree_list);
 static bool check_log_statement_cooked(List *parsetree_list);
-static bool check_log_duration(char *msec_str);
 static int errdetail_execute(List *raw_parsetree_list);
 static int errdetail_params(ParamListInfo params);
 static void start_xact_command(void);
@@ -995,16 +994,18 @@ exec_simple_query(const char *query_string)
    /*
     * Emit duration logging if appropriate.
     */
-   if (check_log_duration(msec_str))
+   switch (check_log_duration(msec_str, was_logged))
    {
-       if (was_logged)
+       case 1:
            ereport(LOG,
                    (errmsg("duration: %s ms", msec_str)));
-       else
+           break;
+       case 2:
            ereport(LOG,
                    (errmsg("duration: %s ms  statement: %s",
                            msec_str, query_string),
                     errdetail_execute(parsetree_list)));
+           break;
    }
 
    if (save_log_statement_stats)
@@ -1247,12 +1248,20 @@ exec_parse_message(const char *query_string,    /* string to execute */
    /*
     * Emit duration logging if appropriate.
     */
-   if (check_log_duration(msec_str))
-       ereport(LOG,
-               (errmsg("duration: %s ms  parse %s: %s",
-                       msec_str,
-                       *stmt_name ? stmt_name : "",
-                       query_string)));
+   switch (check_log_duration(msec_str, false))
+   {
+       case 1:
+           ereport(LOG,
+                   (errmsg("duration: %s ms", msec_str)));
+           break;
+       case 2:
+           ereport(LOG,
+                   (errmsg("duration: %s ms  parse %s: %s",
+                           msec_str,
+                           *stmt_name ? stmt_name : "",
+                           query_string)));
+           break;
+   }
 
    if (save_log_statement_stats)
        ShowUsage("PARSE MESSAGE STATISTICS");
@@ -1593,14 +1602,22 @@ exec_bind_message(StringInfo input_message)
    /*
     * Emit duration logging if appropriate.
     */
-   if (check_log_duration(msec_str))
-       ereport(LOG,
-               (errmsg("duration: %s ms  bind %s to %s: %s",
-                       msec_str,
-                       *portal_name ? portal_name : "",
-                       *stmt_name ? stmt_name : "",
-                       pstmt->query_string ? pstmt->query_string : ""),
-                errdetail_params(params)));
+   switch (check_log_duration(msec_str, false))
+   {
+       case 1:
+           ereport(LOG,
+                   (errmsg("duration: %s ms", msec_str)));
+           break;
+       case 2:
+           ereport(LOG,
+                   (errmsg("duration: %s ms  bind %s to %s: %s",
+                           msec_str,
+                           *portal_name ? portal_name : "",
+                           *stmt_name ? stmt_name : "",
+                           pstmt->query_string ? pstmt->query_string : ""),
+                    errdetail_params(params)));
+           break;
+   }
 
    if (save_log_statement_stats)
        ShowUsage("BIND MESSAGE STATISTICS");
@@ -1794,12 +1811,13 @@ exec_execute_message(const char *portal_name, long max_rows)
    /*
     * Emit duration logging if appropriate.
     */
-   if (check_log_duration(msec_str))
+   switch (check_log_duration(msec_str, was_logged))
    {
-       if (was_logged)
+       case 1:
            ereport(LOG,
                    (errmsg("duration: %s ms", msec_str)));
-       else
+           break;
+       case 2:
            ereport(LOG,
                    (errmsg("duration: %s ms  %s %s%s%s%s%s",
                            msec_str,
@@ -1812,6 +1830,7 @@ exec_execute_message(const char *portal_name, long max_rows)
                            sourceText ? ": " : "",
                            sourceText ? sourceText : ""),
                     errdetail_params(portalParams)));
+           break;
    }
 
    if (save_log_statement_stats)
@@ -1878,17 +1897,26 @@ check_log_statement_cooked(List *parsetree_list)
  * check_log_duration
  *     Determine whether current command's duration should be logged
  *
+ * Returns:
+ *     0 if no logging is needed
+ *     1 if just the duration should be logged
+ *     2 if duration and query details should be logged
+ *
  * If logging is needed, the duration in msec is formatted into msec_str[],
  * which must be a 32-byte buffer.
+ *
+ * was_logged should be TRUE if caller already logged query details (this
+ * essentially prevents 2 from being returned).
  */
-static bool
-check_log_duration(char *msec_str)
+int
+check_log_duration(char *msec_str, bool was_logged)
 {
    if (log_duration || log_min_duration_statement >= 0)
    {
        long        secs;
        int         usecs;
        int         msecs;
+       bool        exceeded;
 
        TimestampDifference(GetCurrentStatementStartTimestamp(),
                            GetCurrentTimestamp(),
@@ -1896,24 +1924,28 @@ check_log_duration(char *msec_str)
        msecs = usecs / 1000;
 
        /*
-        * The odd-looking test for log_min_duration_statement being
+        * This odd-looking test for log_min_duration_statement being
         * exceeded is designed to avoid integer overflow with very
         * long durations: don't compute secs * 1000 until we've
         * verified it will fit in int.
         */
-       if (log_duration ||
-           log_min_duration_statement == 0 ||
-           (log_min_duration_statement > 0 &&
-            (secs > log_min_duration_statement / 1000 ||
-             secs * 1000 + msecs >= log_min_duration_statement)))
+       exceeded = (log_min_duration_statement == 0 ||
+                   (log_min_duration_statement > 0 &&
+                    (secs > log_min_duration_statement / 1000 ||
+                     secs * 1000 + msecs >= log_min_duration_statement)));
+
+       if (exceeded || log_duration)
        {
            snprintf(msec_str, 32, "%ld.%03d",
                     secs * 1000 + msecs, usecs % 1000);
-           return true;
+           if (exceeded && !was_logged)
+               return 2;
+           else
+               return 1;
        }
    }
 
-   return false;
+   return 0;
 }
 
 /*

diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index fd87d87adba30c0e3918c0f69ac236d8db298203..a2913e95a159113b8038ffaef4085ee720568d7e 100644 (file)
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.82 2006/07/13 18:01:02 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.83 2006/09/08 15:55:53 tgl Exp $
  *
  * OLD COMMENTS
  *   This file was created so that other c files could get the two
@@ -64,6 +64,7 @@ extern void client_read_ended(void);
 extern int PostgresMain(int argc, char *argv[], const char *username);
 extern void ResetUsage(void);
 extern void ShowUsage(const char *title);
+extern int check_log_duration(char *msec_str, bool was_logged);
 extern void set_debug_options(int debug_flag,
                  GucContext context, GucSource source);
 extern bool set_plan_disabling_options(const char *arg,