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.

1 files changed, 64 insertions, 32 deletions

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 30c722f4adb..0344eec53fc 100644
--- 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 : "<unnamed>",
-						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 : "<unnamed>",
+							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 : "<unnamed>",
-						*stmt_name ? stmt_name : "<unnamed>",
-						pstmt->query_string ? pstmt->query_string : "<source not stored>"),
-				 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 : "<unnamed>",
+							*stmt_name ? stmt_name : "<unnamed>",
+							pstmt->query_string ? pstmt->query_string : "<source not stored>"),
+					 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;
 }
 
 /*