Add log_min_duration_statement.

Christopher Kings-Lynne

doc/src/sgml/runtime.sgml

 <!--
-$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>

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");
 	}
 
 	/*

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
 	}

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

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",

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 */