Remove redundant gettimeofday() calls to the extent practical without

changing semantics too much.  statement_timestamp is now set immediately
upon receipt of a client command message, and the various places that used
to do their own gettimeofday() calls to mark command startup are referenced
to that instead.  I have also made stats_command_string use that same
value for pg_stat_activity.query_start for both the command itself and
its eventual replacement by <IDLE> or <idle in transaction>.  There was
some debate about that, but no argument that seemed convincing enough to
justify an extra gettimeofday() call.

1 files changed, 122 insertions, 165 deletions

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index b7c363d80cd..227498d1f67 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.488 2006/06/18 15:38:37 petere Exp $
+ *	  $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.489 2006/06/20 22:52:00 tgl Exp $
  *
  * NOTES
  *	  this is the "main" module of the postgres backend and
@@ -119,12 +119,6 @@ static volatile sig_atomic_t got_SIGHUP = false;
 static bool xact_started = false;
 
 /*
- * Flag to keep track of whether we have done statement initialization.
- * For extended query protocol this has to be remembered across messages.
- */
-static bool command_initialized = false;
-
-/*
  * Flag to indicate that we are doing the outer loop's read-from-client,
  * as opposed to any random read from client that might happen within
  * commands like COPY FROM STDIN.
@@ -170,8 +164,6 @@ static int	ReadCommand(StringInfo inBuf);
 static bool log_after_parse(List *raw_parsetree_list,
 				const char *query_string, char **prepare_string);
 static List *pg_rewrite_queries(List *querytree_list);
-static void initialize_command(void);
-static void finalize_command(void);
 static void start_xact_command(void);
 static void finish_xact_command(void);
 static bool IsTransactionExitStmt(Node *parsetree);
@@ -832,10 +824,6 @@ exec_simple_query(const char *query_string)
 	MemoryContext oldcontext;
 	List	   *parsetree_list;
 	ListCell   *parsetree_item;
-	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;
 	char	   *prepare_string = NULL;
 	bool		was_logged = false;
@@ -848,14 +836,9 @@ exec_simple_query(const char *query_string)
 	pgstat_report_activity(query_string);
 
 	/*
-	 * 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.
+	 * We use save_log_statement_stats so ShowUsage doesn't report incorrect
+	 * results because ResetUsage wasn't called.
 	 */
-	if (save_log_duration || save_log_min_duration_statement != -1)
-		gettimeofday(&start_t, NULL);
-
 	if (save_log_statement_stats)
 		ResetUsage();
 
@@ -866,7 +849,7 @@ exec_simple_query(const char *query_string)
 	 * one of those, else bad things will happen in xact.c. (Note that this
 	 * will normally change current memory context.)
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/*
 	 * Zap any pre-existing unnamed statement.	(While not strictly necessary,
@@ -895,7 +878,8 @@ exec_simple_query(const char *query_string)
 	 */
 	parsetree_list = pg_parse_query(query_string);
 
-	if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1)
+	/* Log immediately if dictated by log_statement */
+	if (log_statement != LOGSTMT_NONE)
 		was_logged = log_after_parse(parsetree_list, query_string,
 									 &prepare_string);
 
@@ -1075,7 +1059,7 @@ exec_simple_query(const char *query_string)
 	/*
 	 * Close down transaction statement, if one is open.
 	 */
-	finalize_command();
+	finish_xact_command();
 
 	/*
 	 * If there were no parsetrees, return EmptyQueryResponse message.
@@ -1086,44 +1070,42 @@ exec_simple_query(const char *query_string)
 	QueryContext = NULL;
 
 	/*
-	 * Combine processing here as we need to calculate the query duration in
-	 * both instances.
+	 * Emit duration logging if appropriate.
 	 */
-	if (save_log_duration || save_log_min_duration_statement != -1)
+	if (log_duration || log_min_duration_statement >= 0)
 	{
-		long		usecs;
+		long		secs;
+		int			usecs;
+		int			msecs;
 
-		gettimeofday(&stop_t, NULL);
-		if (stop_t.tv_usec < start_t.tv_usec)
-		{
-			stop_t.tv_sec--;
-			stop_t.tv_usec += 1000000;
-		}
-		usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
-			(long) (stop_t.tv_usec - start_t.tv_usec);
-
-		/* Only print duration if we previously printed the statement. */
-		if (was_logged && save_log_duration)
-			ereport(LOG,
-					(errmsg("duration: %ld.%03ld ms",
-							(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)));
+		TimestampDifference(GetCurrentStatementStartTimestamp(),
+							GetCurrentTimestamp(),
+							&secs, &usecs);
+		msecs = usecs / 1000;
 
 		/*
-		 * Output a duration_statement to the log if the query has exceeded
-		 * the min duration, or if we are to print all durations.
+		 * The 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 (save_log_min_duration_statement == 0 ||
-			(save_log_min_duration_statement > 0 &&
-			 usecs >= save_log_min_duration_statement * 1000))
-			ereport(LOG,
-					(errmsg("duration: %ld.%03ld ms  statement: %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,
-							query_string,
-							prepare_string ? prepare_string : "")));
+		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)))
+		{
+			if (was_logged)
+				ereport(LOG,
+						(errmsg("duration: %ld.%03d ms",
+								secs, msecs)));
+			else
+				ereport(LOG,
+						(errmsg("duration: %ld.%03d ms  statement: %s%s",
+								secs, msecs,
+								query_string,
+								prepare_string ? prepare_string : "")));
+		}
 	}
 
 	if (save_log_statement_stats)
@@ -1178,7 +1160,7 @@ exec_parse_message(const char *query_string,	/* string to execute */
 	 * that this will normally change current memory context.) Nothing happens
 	 * if we are already in one.
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/*
 	 * Switch to appropriate context for constructing parsetrees.
@@ -1401,7 +1383,7 @@ exec_bind_message(StringInfo input_message)
 	 * this will normally change current memory context.) Nothing happens if
 	 * we are already in one.
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/* Switch back to message context */
 	MemoryContextSwitchTo(MessageContext);
@@ -1678,10 +1660,6 @@ exec_execute_message(const char *portal_name, long max_rows)
 	Portal		portal;
 	bool		completed;
 	char		completionTag[COMPLETION_TAG_BUFSIZE];
-	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;
 	bool		execute_is_fetch = false;
 
@@ -1736,14 +1714,9 @@ exec_execute_message(const char *portal_name, long max_rows)
 	set_ps_display(portal->commandTag);
 
 	/*
-	 * 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.
+	 * We use save_log_statement_stats so ShowUsage doesn't report incorrect
+	 * results because ResetUsage wasn't called.
 	 */
-	if (save_log_duration || save_log_min_duration_statement != -1)
-		gettimeofday(&start_t, NULL);
-
 	if (save_log_statement_stats)
 		ResetUsage();
 
@@ -1751,8 +1724,8 @@ exec_execute_message(const char *portal_name, long max_rows)
 		/* We have the portal, so output the source query. */
 		ereport(LOG,
 				(errmsg("statement: [protocol] %sEXECUTE %s  [PREPARE:  %s]",
-						(execute_is_fetch) ? "FETCH from " : "",
-						(*portal_name != '\0') ? portal_name : "<unnamed>",
+						execute_is_fetch ? "FETCH from " : "",
+						(*portal_name) ? portal_name : "<unnamed>",
 						portal->sourceText ? portal->sourceText : "")));
 
 	BeginCommand(portal->commandTag, dest);
@@ -1767,7 +1740,7 @@ exec_execute_message(const char *portal_name, long max_rows)
 	 * Ensure we are in a transaction command (this should normally be the
 	 * case already due to prior BIND).
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/*
 	 * If we are in aborted transaction state, the only portals we can
@@ -1827,45 +1800,43 @@ exec_execute_message(const char *portal_name, long max_rows)
 	}
 
 	/*
-	 * Combine processing here as we need to calculate the query duration in
-	 * both instances.
+	 * Emit duration logging if appropriate.
 	 */
-	if (save_log_duration || save_log_min_duration_statement != -1)
+	if (log_duration || log_min_duration_statement >= 0)
 	{
-		long		usecs;
+		long		secs;
+		int			usecs;
+		int			msecs;
 
-		gettimeofday(&stop_t, NULL);
-		if (stop_t.tv_usec < start_t.tv_usec)
-		{
-			stop_t.tv_sec--;
-			stop_t.tv_usec += 1000000;
-		}
-		usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
-			(long) (stop_t.tv_usec - start_t.tv_usec);
-
-		/* Only print duration if we previously printed the statement. */
-		if (log_statement == LOGSTMT_ALL && save_log_duration)
-			ereport(LOG,
-					(errmsg("duration: %ld.%03ld ms",
-							(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)));
+		TimestampDifference(GetCurrentStatementStartTimestamp(),
+							GetCurrentTimestamp(),
+							&secs, &usecs);
+		msecs = usecs / 1000;
 
 		/*
-		 * Output a duration_statement to the log if the query has exceeded
-		 * the min duration, or if we are to print all durations.
+		 * The 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 (save_log_min_duration_statement == 0 ||
-			(save_log_min_duration_statement > 0 &&
-			 usecs >= save_log_min_duration_statement * 1000))
-			ereport(LOG,
-					(errmsg("duration: %ld.%03ld ms  statement: [protocol] %sEXECUTE %s  [PREPARE:  %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,
-							(execute_is_fetch) ? "FETCH from " : "",
-						  (*portal_name != '\0') ? portal_name : "<unnamed>",
+		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)))
+		{
+			if (log_statement == LOGSTMT_ALL)	/* already logged? */
+				ereport(LOG,
+						(errmsg("duration: %ld.%03d ms",
+								secs, msecs)));
+			else
+				ereport(LOG,
+						(errmsg("duration: %ld.%03d ms  statement: [protocol] %sEXECUTE %s  [PREPARE:  %s]",
+								secs, msecs,
+								execute_is_fetch ? "FETCH from " : "",
+								(*portal_name) ? portal_name : "<unnamed>",
 							portal->sourceText ? portal->sourceText : "")));
+		}
 	}
 
 	if (save_log_statement_stats)
@@ -1891,7 +1862,7 @@ exec_describe_statement_message(const char *stmt_name)
 	 * Start up a transaction command. (Note that this will normally change
 	 * current memory context.) Nothing happens if we are already in one.
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/* Switch back to message context */
 	MemoryContextSwitchTo(MessageContext);
@@ -1969,7 +1940,7 @@ exec_describe_portal_message(const char *portal_name)
 	 * Start up a transaction command. (Note that this will normally change
 	 * current memory context.) Nothing happens if we are already in one.
 	 */
-	initialize_command();
+	start_xact_command();
 
 	/* Switch back to message context */
 	MemoryContextSwitchTo(MessageContext);
@@ -2008,55 +1979,24 @@ exec_describe_portal_message(const char *portal_name)
 
 
 /*
- *	Start xact if necessary, and set statement_timestamp() and optionally
- *	statement_timeout.
+ * Convenience routines for starting/committing a single command.
  */
 static void
-initialize_command(void)
+start_xact_command(void)
 {
-	if (!command_initialized)
+	if (!xact_started)
 	{
-		SetCurrentStatementStartTimestamp();
+		ereport(DEBUG3,
+				(errmsg_internal("StartTransactionCommand")));
+		StartTransactionCommand();
 
 		/* Set statement timeout running, if any */
+		/* NB: this mustn't be enabled until we are within an xact */
 		if (StatementTimeout > 0)
 			enable_sig_alarm(StatementTimeout, true);
 		else
 			cancel_from_timeout = false;
 
-		command_initialized = true;
-	}
-	start_xact_command();
-}
-
-static void
-finalize_command(void)
-{
-	if (command_initialized)
-	{
-		/* Cancel any active statement timeout before committing */
-		disable_sig_alarm(true);
-
-		command_initialized = false;
-	}
-	finish_xact_command();
-}
-
-
-/*
- *	Check if the newly-arrived query string needs to have an implicit
- *	transaction started.
- */
-static void
-start_xact_command(void)
-{
-	if (!xact_started)
-	{
-		ereport(DEBUG3,
-				(errmsg_internal("StartTransactionCommand")));
-
-		StartTransactionCommand();
-
 		xact_started = true;
 	}
 }
@@ -2066,6 +2006,10 @@ finish_xact_command(void)
 {
 	if (xact_started)
 	{
+		/* Cancel any active statement timeout before committing */
+		disable_sig_alarm(true);
+
+		/* Now commit the command */
 		ereport(DEBUG3,
 				(errmsg_internal("CommitTransactionCommand")));
 
@@ -3127,8 +3071,7 @@ PostgresMain(int argc, char *argv[], const char *username)
 
 		/* We don't have a transaction command open anymore */
 		xact_started = false;
-		command_initialized = false;
-		
+
 		/* Now we can allow interrupts again */
 		RESUME_INTERRUPTS();
 	}
@@ -3235,6 +3178,9 @@ PostgresMain(int argc, char *argv[], const char *username)
 				{
 					const char *query_string;
 
+					/* Set statement_timestamp() */
+					SetCurrentStatementStartTimestamp();
+
 					query_string = pq_getmsgstring(&input_message);
 					pq_getmsgend(&input_message);
 
@@ -3251,6 +3197,9 @@ PostgresMain(int argc, char *argv[], const char *username)
 					int			numParams;
 					Oid		   *paramTypes = NULL;
 
+					/* Set statement_timestamp() */
+					SetCurrentStatementStartTimestamp();
+
 					stmt_name = pq_getmsgstring(&input_message);
 					query_string = pq_getmsgstring(&input_message);
 					numParams = pq_getmsgint(&input_message, 2);
@@ -3270,6 +3219,8 @@ PostgresMain(int argc, char *argv[], const char *username)
 				break;
 
 			case 'B':			/* bind */
+				/* Set statement_timestamp() */
+				SetCurrentStatementStartTimestamp();
 
 				/*
 				 * this message is complex enough that it seems best to put
@@ -3283,6 +3234,9 @@ PostgresMain(int argc, char *argv[], const char *username)
 					const char *portal_name;
 					int			max_rows;
 
+					/* Set statement_timestamp() */
+					SetCurrentStatementStartTimestamp();
+
 					portal_name = pq_getmsgstring(&input_message);
 					max_rows = pq_getmsgint(&input_message, 4);
 					pq_getmsgend(&input_message);
@@ -3292,11 +3246,14 @@ PostgresMain(int argc, char *argv[], const char *username)
 				break;
 
 			case 'F':			/* fastpath function call */
+				/* Set statement_timestamp() */
+				SetCurrentStatementStartTimestamp();
+
 				/* Tell the collector what we're doing */
 				pgstat_report_activity("<FASTPATH> function call");
 
 				/* start an xact for this function invocation */
-				initialize_command();
+				start_xact_command();
 
 				/*
 				 * Note: we may at this point be inside an aborted
@@ -3325,7 +3282,7 @@ PostgresMain(int argc, char *argv[], const char *username)
 				}
 
 				/* commit the function-invocation transaction */
-				finalize_command();
+				finish_xact_command();
 
 				send_ready_for_query = true;
 				break;
@@ -3383,6 +3340,9 @@ PostgresMain(int argc, char *argv[], const char *username)
 					int			describe_type;
 					const char *describe_target;
 
+					/* Set statement_timestamp() (needed for xact) */
+					SetCurrentStatementStartTimestamp();
+
 					describe_type = pq_getmsgbyte(&input_message);
 					describe_target = pq_getmsgstring(&input_message);
 					pq_getmsgend(&input_message);
@@ -3413,7 +3373,7 @@ PostgresMain(int argc, char *argv[], const char *username)
 
 			case 'S':			/* sync */
 				pq_getmsgend(&input_message);
-				finalize_command();
+				finish_xact_command();
 				send_ready_for_query = true;
 				break;
 
@@ -3588,30 +3548,27 @@ static void
 log_disconnections(int code, Datum arg)
 {
 	Port	   *port = MyProcPort;
-	struct timeval end;
+	long		secs;
+	int			usecs;
+	int			msecs;
 	int			hours,
 				minutes,
 				seconds;
 
-	gettimeofday(&end, NULL);
-	if (end.tv_usec < port->session_start.tv_usec)
-	{
-		end.tv_sec--;
-		end.tv_usec += 1000000;
-	}
-	end.tv_sec -= port->session_start.tv_sec;
-	end.tv_usec -= port->session_start.tv_usec;
+	TimestampDifference(port->SessionStartTime,
+						GetCurrentTimestamp(),
+						&secs, &usecs);
+	msecs = usecs / 1000;
 
-	/* for stricter accuracy here we could round - this is close enough */
-	hours = end.tv_sec / SECS_PER_HOUR;
-	end.tv_sec %= SECS_PER_HOUR;
-	minutes = end.tv_sec / SECS_PER_MINUTE;
-	seconds = end.tv_sec % SECS_PER_MINUTE;
+	hours = secs / SECS_PER_HOUR;
+	secs %= SECS_PER_HOUR;
+	minutes = secs / SECS_PER_MINUTE;
+	seconds = secs % SECS_PER_MINUTE;
 
 	ereport(LOG,
-			(errmsg("disconnection: session time: %d:%02d:%02d.%02d "
+			(errmsg("disconnection: session time: %d:%02d:%02d.%03d "
 					"user=%s database=%s host=%s%s%s",
-					hours, minutes, seconds, (int) (end.tv_usec / 10000),
+					hours, minutes, seconds, msecs,
 					port->user_name, port->database_name, port->remote_host,
-				  port->remote_port[0] ? " port=" : "", port->remote_port)));
+					port->remote_port[0] ? " port=" : "", port->remote_port)));
 }