Add log_min_duration_statement.

Christopher Kings-Lynne

diff --git a/doc/src/sgml/runtime.sgml b/doc/src/sgml/runtime.sgml
index b59cda7e35fa44e7f1f5c09bbc72bcd8204a4638..f90800ab5e1ee13119c3ecbc7a3fec8459278385 100644 (file)
--- a/doc/src/sgml/runtime.sgml
+++ b/doc/src/sgml/runtime.sgml
@@ -1,5 +1,5 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.182 2003/05/27 17:49:45 momjian Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.183 2003/06/11 18:01:13 momjian Exp $
 -->
 
 <Chapter Id="runtime">
@@ -1051,6 +1051,23 @@ SET ENABLE_SEQSCAN TO OFF;
       </listitem>
      </varlistentry>
 
+     <varlistentry>
+      <term><varname>LOG_MIN_DURATION_STATEMENT</varname> (<type>integer</type>)</term>
+      <listitem>
+       <para>
+        Sets a minimum statement execution time (in milliseconds)
+   above which a statement will be logged.  All SQL statements
+   that run longer than the time specified will be logged together
+   with the duration, in seconds.  The default is <literal>0</literal>
+   (turning this feature off).  For example, if you set it
+   to <literal>250</literal> then all SQL statements that run longer
+   than 250ms will be logged along with the duration.  Enabling this
+   option can be useful in tracking down unoptimized queries in
+   your applications.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry>
       <term><varname>LOG_MIN_ERROR_STATEMENT</varname> (<type>string</type>)</term>
       <listitem>

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 6fa751640d591dc0f10783fbbb90ba1f63bd85c1..96f3ca00e69f3df74f35b0cdb289d72f37cbdad2 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.346 2003/05/27 17:49:46 momjian Exp $
+ *   $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.347 2003/06/11 18:01:14 momjian Exp $
  *
  * NOTES
  *   this is the "main" module of the postgres backend and
@@ -663,6 +663,7 @@ exec_simple_query(const char *query_string)
    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;
 
    /*
@@ -673,11 +674,12 @@ exec_simple_query(const char *query_string)
    pgstat_report_activity(query_string);
 
    /*
-    * We use save_log_duration so "SET log_duration = true" doesn't
-    * report incorrect time because gettimeofday() wasn't called.
+    * 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)
+   if (save_log_duration || save_log_min_duration_statement > 0)
        gettimeofday(&start_t, NULL);
 
    if (save_log_statement_stats)
@@ -915,19 +917,38 @@ exec_simple_query(const char *query_string)
    QueryContext = NULL;
 
    /*
-    * Finish up monitoring.
+    * Combine processing here as we need to calculate the query
+    * duration in both instances.
     */
-   if (save_log_duration)
+   if (save_log_duration || save_log_min_duration_statement > 0)
    {
+       long usecs;
        gettimeofday(&stop_t, NULL);
        if (stop_t.tv_usec < start_t.tv_usec)
        {
            stop_t.tv_sec--;
            stop_t.tv_usec += 1000000;
        }
-       elog(LOG, "duration: %ld.%06ld sec",
-            (long) (stop_t.tv_sec - start_t.tv_sec),
-            (long) (stop_t.tv_usec - start_t.tv_usec));
+       usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);
+
+       /* 
+        * Output a duration_query to the log if the query has exceeded the
+        * min duration.
+        */
+       if (usecs >= save_log_min_duration_statement * 1000)
+           elog(LOG, "duration_statement: %ld.%06ld %s",
+               (long) (stop_t.tv_sec - start_t.tv_sec),
+               (long) (stop_t.tv_usec - start_t.tv_usec),
+               query_string);
+
+       /* 
+        * If the user is requesting logging of all durations, then log
+        * that as well.
+        */
+       if (save_log_duration)
+           elog(LOG, "duration: %ld.%06ld sec",
+                (long) (stop_t.tv_sec - start_t.tv_sec),
+                (long) (stop_t.tv_usec - start_t.tv_usec));
    }
 
    if (save_log_statement_stats)
@@ -2526,7 +2547,7 @@ PostgresMain(int argc, char *argv[], const char *username)
    if (!IsUnderPostmaster)
    {
        puts("\nPOSTGRES backend interactive interface ");
-       puts("$Revision: 1.346 $ $Date: 2003/05/27 17:49:46 $\n");
+       puts("$Revision: 1.347 $ $Date: 2003/06/11 18:01:14 $\n");
    }
 
    /*

diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 94e7e5b65dbafdf4a1f0e1436def4eeffe01002e..d75803621ca08527c4590210cb4d505ad5591282 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -10,7 +10,7 @@
  * Written by Peter Eisentraut <peter_e@gmx.net>.
  *
  * IDENTIFICATION
- *   $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.128 2003/06/11 05:04:51 momjian Exp $
+ *   $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.129 2003/06/11 18:01:14 momjian Exp $
  *
  *--------------------------------------------------------------------
  */
@@ -55,6 +55,8 @@
 #include "utils/pg_locale.h"
 #include "pgstat.h"
 
+int            log_min_duration_statement = 0;
+
 
 #ifndef PG_KRB_SRVTAB
 #define PG_KRB_SRVTAB ""
@@ -735,6 +737,11 @@ static struct config_int
        0, -15, 2, NULL, NULL
    },
 
+   {
+       {"log_min_duration_statement", PGC_USERSET}, &log_min_duration_statement,
+       0, 0, INT_MAX / 1000, NULL, NULL
+   },
+
    {
        {NULL, 0}, NULL, 0, 0, 0, NULL, NULL
    }

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 9c0bb8caea885405f85c8651072785d1e85b80aa..77858388c3e88b028365a09fdf3a150819ad940f 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -140,6 +140,10 @@
                 #   debug5, debug4, debug3, debug2, debug1,
                 #   info, notice, warning, error, panic(off)
 
+#log_min_duration_statement = 0  # Log all statements whose
+                # execution time exceeds the value, in
+                # milliseconds.  Zero disables.
+
 #debug_print_parse = false
 #debug_print_rewritten = false
 #debug_print_plan = false

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index ea2295cca42b0fbf9c4cb6a4fbaec865283153d4..0946bab9cd98889cb5b932ed0d1a2b939b6cac34 100644 (file)
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -3,7 +3,7 @@
  *
  * Copyright 2000-2002 by PostgreSQL Global Development Group
  *
- * $Header: /cvsroot/pgsql/src/bin/psql/tab-complete.c,v 1.77 2003/05/14 03:26:02 tgl Exp $
+ * $Header: /cvsroot/pgsql/src/bin/psql/tab-complete.c,v 1.78 2003/06/11 18:01:14 momjian Exp $
  */
 
 /*----------------------------------------------------------------------
@@ -538,6 +538,7 @@ psql_completion(char *text, int start, int end)
        "lc_time",
        "log_duration",
        "log_executor_stats",
+       "log_min_duration_statement",
        "log_min_error_statement",
        "log_min_messages",
        "log_parser_stats",

diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index c9b4b93ce519086c71271f4d23e180cd76fee5f4..2926f0a41341873b4eca7011cd224386fcd8ec9c 100644 (file)
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -7,7 +7,7 @@
  * Copyright 2000-2003 by PostgreSQL Global Development Group
  * Written by Peter Eisentraut <peter_e@gmx.net>.
  *
- * $Id: guc.h,v 1.31 2003/05/06 20:26:28 tgl Exp $
+ * $Id: guc.h,v 1.32 2003/06/11 18:01:14 momjian Exp $
  *--------------------------------------------------------------------
  */
 #ifndef GUC_H
@@ -142,4 +142,6 @@ void write_nondefault_variables(GucContext context);
 void read_nondefault_variables(void);
 #endif
 
+extern int log_min_duration_statement;
+
 #endif   /* GUC_H */