Have log_min_duration_statement = 0 always print duration/statement.

Change log line to be "duration:  ms  query:"

Indent multi-line queries with a tab in the server logs.

Author: bmomjian

doc/src/sgml/runtime.sgml

@@ -1,5 +1,5 @@
 <!--
-$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.210 2003/10/03 19:26:49 tgl Exp $
+$Header: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v 1.211 2003/10/08 03:49:37 momjian Exp $
 -->
 
 <Chapter Id="runtime">
@@ -1689,16 +1689,16 @@ SET ENABLE_SEQSCAN TO OFF;
        <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 their actual duration.  Setting this to zero (the default)
-	 disables time-based logging.  For example, if you set it
-         to <literal>250</literal> then all SQL statements that run longer
-         than 250ms will be logged.  Enabling this
-         option can be useful in tracking down unoptimized queries in
-         your applications.
-         Only superusers can increase this or set it to zero if this option
-         is set to non-zero by the administrator.
+         for statement to be logged.  All SQL statements
+         that run in the time specified or longer will be logged with
+         their duration.  Setting this to zero will print
+         all queries and their durations.  Minus-one (the default)
+         disables this.  For example, if you set it to 
+         <literal>250</literal> then all SQL statements that run 250ms 
+         or longer will be logged.  Enabling this option can be
+         useful in tracking down unoptimized queries in your applications.
+         Only superusers can increase this or set it to minus-one if this 
+         option is set by the administrator.
         </para>
        </listitem>
       </varlistentry>

src/backend/tcop/postgres.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.370 2003/10/04 02:47:04 momjian Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.371 2003/10/08 03:49:37 momjian Exp $
  *
  * NOTES
  *	  this is the "main" module of the postgres backend and
@@ -694,7 +694,7 @@ exec_simple_query(const char *query_string)
 	 * because gettimeofday() wasn't called. Similarly,
 	 * log_statement_stats has to be captured once.
 	 */
-	if (save_log_duration || save_log_min_duration_statement > 0)
+	if (save_log_duration || save_log_min_duration_statement != -1)
 		gettimeofday(&start_t, NULL);
 
 	if (save_log_statement_stats)
@@ -940,7 +940,7 @@ exec_simple_query(const char *query_string)
 	 * Combine processing here as we need to calculate the query duration
 	 * in both instances.
 	 */
-	if (save_log_duration || save_log_min_duration_statement > 0)
+	if (save_log_duration || save_log_min_duration_statement != -1)
 	{
 		long		usecs;
 		bool		print_statement;
@@ -957,15 +957,17 @@ exec_simple_query(const char *query_string)
 		 * Output a duration_statement to the log if the query has exceeded
 		 * the min duration, or if we are to print all durations.
 		 */
-		print_statement = (save_log_min_duration_statement > 0 &&
-						   usecs >= save_log_min_duration_statement * 1000);
+		print_statement = (save_log_min_duration_statement == 0 ||
+						   (save_log_min_duration_statement > 0 &&
+						    usecs >= save_log_min_duration_statement * 1000));
 
 		if (save_log_duration || print_statement)
 			ereport(LOG,
-					(errmsg("duration(secs): %ld.%06ld%s%s",
-							(long) (stop_t.tv_sec - start_t.tv_sec),
-							(long) (stop_t.tv_usec - start_t.tv_usec),
-							print_statement ? " " : "",
+					(errmsg("duration: %ld.%03ld ms%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,
+							print_statement ? "  query: " : "",
 							print_statement ? query_string : "")));
 	}
 
@@ -2655,7 +2657,7 @@ PostgresMain(int argc, char *argv[], const char *username)
 	if (!IsUnderPostmaster)
 	{
 		puts("\nPOSTGRES backend interactive interface ");
-		puts("$Revision: 1.370 $ $Date: 2003/10/04 02:47:04 $\n");
+		puts("$Revision: 1.371 $ $Date: 2003/10/08 03:49:37 $\n");
 	}
 
 	/*
@@ -3196,3 +3198,4 @@ ShowUsage(const char *title)
 
 	pfree(str.data);
 }
+

src/backend/utils/error/elog.c

@@ -37,7 +37,7 @@
  *
  *
  * IDENTIFICATION
- *	  $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.123 2003/09/25 06:58:05 petere Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.124 2003/10/08 03:49:38 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -145,6 +145,7 @@ static const char *useful_strerror(int errnum);
 static const char *error_severity(int elevel);
 static const char *print_timestamp(void);
 static const char *print_pid(void);
+static char *str_prepend_tabs(const char *str);
 
 
 /*
@@ -1135,14 +1136,17 @@ send_message_to_server_log(ErrorData *edata)
 	/* Write to stderr, if enabled */
 	if (Use_syslog <= 1 || whereToSendOutput == Debug)
 	{
+		char *p = str_prepend_tabs(buf.data);
+
 		/*
 		 * Timestamp and PID are only used for stderr output --- we assume
 		 * the syslog daemon will supply them for us in the other case.
 		 */
 		fprintf(stderr, "%s%s%s",
 				Log_timestamp ? print_timestamp() : "",
 				Log_pid ? print_pid() : "",
-				buf.data);
+				p);
+		pfree(p);
 	}
 
 	pfree(buf.data);
@@ -1450,3 +1454,24 @@ print_pid(void)
 	snprintf(buf, sizeof(buf), "[%d] ", (int) MyProcPid);
 	return buf;
 }
+
+/*
+ *	str_prepend_tabs
+ *
+ *	This string prepends a tab to message continuation lines.
+ */
+static char *str_prepend_tabs(const char *str)
+{
+	char *outstr = palloc(strlen(str) * 2 + 1);
+	int	len = strlen(str);
+	int i, outlen = 0;
+
+	for (i = 0; i < len; i++)
+	{
+		outstr[outlen++] = str[i];
+		if (str[i] == '\n' && str[i+1] != '\0' )
+			outstr[outlen++] = '\t';
+	}
+	outstr[outlen++]	= '\0';
+	return outstr;
+}

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.162 2003/10/03 19:26:49 tgl Exp $
+ *	  $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.163 2003/10/08 03:49:38 momjian Exp $
  *
  *--------------------------------------------------------------------
  */
@@ -128,7 +128,7 @@ int			log_min_error_statement = PANIC;
 int			log_min_messages = NOTICE;
 int			client_min_messages = NOTICE;
 
-int			log_min_duration_statement = 0;
+int			log_min_duration_statement = -1;
 
 
 /*
@@ -1185,10 +1185,10 @@ static struct config_int ConfigureNamesInt[] =
 		{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
 			gettext_noop("minimum execution time in milliseconds above which statements will "
 						 "be logged"),
-			gettext_noop("The default is 0 (turning this feature off).")
+			gettext_noop("Zero prints all queries.  The default is -1 (turning this feature off).")
 		},
 		&log_min_duration_statement,
-		0, 0, INT_MAX / 1000, NULL, NULL
+		-1, -1, INT_MAX / 1000, NULL, NULL
 	},
 
 	/* End-of-list marker */

src/backend/utils/misc/postgresql.conf.sample

@@ -157,9 +157,10 @@
 				 #   debug5, debug4, debug3, debug2, debug1,
 				 #   info, notice, warning, error, panic(off)
 
-#log_min_duration_statement = 0  # Log all statements whose
+#log_min_duration_statement = -1 # Log all statements whose
 				 # execution time exceeds the value, in
-				 # milliseconds.  Zero disables.
+				 # milliseconds.  Zero prints all queries.
+				 # Minus-one disables.
 
 #silent_mode = false		 # DO NOT USE without Syslog!