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.

src/backend/access/transam/xact.c

@@ -10,7 +10,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.220 2006/04/25 00:25:17 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.221 2006/06/20 22:51:59 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -167,9 +167,10 @@ static SubTransactionId currentSubTransactionId;
 static CommandId currentCommandId;
 
 /*
- * This is the value of now(), ie, the transaction start time.
- * This does not change as we enter and exit subtransactions, so we don't
- * keep it inside the TransactionState stack.
+ * xactStartTimestamp is the value of transaction_timestamp().
+ * stmtStartTimestamp is the value of statement_timestamp().
+ * These do not change as we enter and exit subtransactions, so we don't
+ * keep them inside the TransactionState stack.
  */
 static TimestampTz xactStartTimestamp;
 static TimestampTz stmtStartTimestamp;
@@ -1386,7 +1387,9 @@ StartTransaction(void)
 	XactLockTableInsert(s->transactionId);
 
 	/*
-	 * now() and statement_timestamp() should be the same time
+	 * set transaction_timestamp() (a/k/a now()).  We want this to be the
+	 * same as the first command's statement_timestamp(), so don't do a
+	 * fresh GetCurrentTimestamp() call (which'd be expensive anyway).
 	 */
 	xactStartTimestamp = stmtStartTimestamp;
 

src/backend/commands/prepare.c

@@ -10,7 +10,7 @@
  * Copyright (c) 2002-2006, PostgreSQL Global Development Group
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.52 2006/04/25 14:11:54 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.53 2006/06/20 22:51:59 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -373,7 +373,7 @@ StorePreparedStatement(const char *stmt_name,
 	entry->plan_list = plan_list;
 	entry->argtype_list = argtype_list;
 	entry->context = entrycxt;
-	entry->prepare_time = GetCurrentTimestamp();
+	entry->prepare_time = GetCurrentStatementStartTimestamp();
 	entry->from_sql = from_sql;
 
 	MemoryContextSwitchTo(oldcxt);

src/backend/postmaster/pgstat.c

@@ -13,7 +13,7 @@
  *
  *	Copyright (c) 2001-2006, PostgreSQL Global Development Group
  *
- *	$PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.129 2006/06/19 01:51:21 tgl Exp $
+ *	$PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.130 2006/06/20 22:52:00 tgl Exp $
  * ----------
  */
 #include "postgres.h"
@@ -1368,7 +1368,13 @@ pgstat_bestart(void)
 	/*
 	 * To minimize the time spent modifying the entry, fetch all the
 	 * needed data first.
+	 *
+	 * If we have a MyProcPort, use its session start time (for consistency,
+	 * and to save a kernel call).
 	 */
+	if (MyProcPort)
+		proc_start_timestamp = MyProcPort->SessionStartTime;
+	else
 		proc_start_timestamp = GetCurrentTimestamp();
 	userid = GetSessionUserId();
 
@@ -1464,7 +1470,7 @@ pgstat_report_activity(const char *cmd_str)
 	 * To minimize the time spent modifying the entry, fetch all the
 	 * needed data first.
 	 */
-	start_timestamp = GetCurrentTimestamp();
+	start_timestamp = GetCurrentStatementStartTimestamp();
 
 	len = strlen(cmd_str);
 	len = pg_mbcliplen(cmd_str, len, PGBE_ACTIVITY_SIZE - 1);

src/backend/postmaster/postmaster.c

@@ -37,7 +37,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.487 2006/06/19 01:51:21 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/postmaster/postmaster.c,v 1.488 2006/06/20 22:52:00 tgl Exp $
  *
  * NOTES
  *
@@ -99,7 +99,6 @@
 #include "commands/async.h"
 #include "lib/dllist.h"
 #include "libpq/auth.h"
-#include "libpq/crypt.h"
 #include "libpq/libpq.h"
 #include "libpq/pqcomm.h"
 #include "libpq/pqsignal.h"
@@ -2609,8 +2608,9 @@ BackendInitialize(Port *port)
 
 	ClientAuthInProgress = true;	/* limit visibility of log messages */
 
-	/* save start time for end of session reporting */
-	gettimeofday(&(port->session_start), NULL);
+	/* save process start time */
+	port->SessionStartTime = GetCurrentTimestamp();
+	port->session_start = timestamptz_to_time_t(port->SessionStartTime);
 
 	/* set these to empty in case they are needed before we set them up */
 	port->remote_host = "";
@@ -2749,6 +2749,8 @@ BackendRun(Port *port)
 	char	  **av;
 	int			maxac;
 	int			ac;
+	long		secs;
+	int			usecs;
 	char		protobuf[32];
 	int			i;
 
@@ -2758,7 +2760,9 @@ BackendRun(Port *port)
 	 * a new random sequence in the random() library function.
 	 */
 	random_seed = 0;
-	srandom((unsigned int) (MyProcPid ^ port->session_start.tv_usec));
+	/* slightly hacky way to get integer microseconds part of timestamptz */
+	TimestampDifference(0, port->SessionStartTime, &secs, &usecs);
+	srandom((unsigned int) (MyProcPid ^ usecs));
 
 	/* ----------------
 	 * Now, build the argv vector that will be given to PostgresMain.

src/backend/storage/lmgr/proc.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.174 2006/04/14 03:38:55 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/proc.c,v 1.175 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -42,6 +42,7 @@
 #include "storage/proc.h"
 #include "storage/procarray.h"
 #include "storage/spin.h"
+#include "utils/timestamp.h"
 
 
 /* GUC variables */
@@ -73,7 +74,7 @@ static volatile bool deadlock_timeout_active = false;
 volatile bool cancel_from_timeout = false;
 
 /* statement_fin_time is valid only if statement_timeout_active is true */
-static struct timeval statement_fin_time;
+static TimestampTz statement_fin_time;
 
 
 static void RemoveProcFromArray(int code, Datum arg);
@@ -1105,29 +1106,32 @@ ProcSendSignal(int pid)
 bool
 enable_sig_alarm(int delayms, bool is_statement_timeout)
 {
-	struct timeval fin_time;
+	TimestampTz fin_time;
 	struct itimerval timeval;
 
-	/* Compute target timeout time if we will need it */
-	if (is_statement_timeout || statement_timeout_active)
-	{
-		gettimeofday(&fin_time, NULL);
-		fin_time.tv_sec += delayms / 1000;
-		fin_time.tv_usec += (delayms % 1000) * 1000;
-		if (fin_time.tv_usec >= 1000000)
-		{
-			fin_time.tv_sec++;
-			fin_time.tv_usec -= 1000000;
-		}
-	}
-
 	if (is_statement_timeout)
 	{
-		/* Begin statement-level timeout */
+		/*
+		 * Begin statement-level timeout
+		 *
+		 * Note that we compute statement_fin_time with reference to the
+		 * statement_timestamp, but apply the specified delay without any
+		 * correction; that is, we ignore whatever time has elapsed since
+		 * statement_timestamp was set.  In the normal case only a small
+		 * interval will have elapsed and so this doesn't matter, but there
+		 * are corner cases (involving multi-statement query strings with
+		 * embedded COMMIT or ROLLBACK) where we might re-initialize the
+		 * statement timeout long after initial receipt of the message.
+		 * In such cases the enforcement of the statement timeout will be
+		 * a bit inconsistent.  This annoyance is judged not worth the cost
+		 * of performing an additional gettimeofday() here.
+		 */
 		Assert(!deadlock_timeout_active);
+		fin_time = GetCurrentStatementStartTimestamp();
+		fin_time = TimestampTzPlusMilliseconds(fin_time, delayms);
 		statement_fin_time = fin_time;
-		statement_timeout_active = true;
 		cancel_from_timeout = false;
+		statement_timeout_active = true;
 	}
 	else if (statement_timeout_active)
 	{
@@ -1145,10 +1149,10 @@ enable_sig_alarm(int delayms, bool is_statement_timeout)
 		 * to the state variables.	The deadlock checker may get run earlier
 		 * than normal, but that does no harm.
 		 */
+		fin_time = GetCurrentTimestamp();
+		fin_time = TimestampTzPlusMilliseconds(fin_time, delayms);
 		deadlock_timeout_active = true;
-		if (fin_time.tv_sec > statement_fin_time.tv_sec ||
-			(fin_time.tv_sec == statement_fin_time.tv_sec &&
-			 fin_time.tv_usec >= statement_fin_time.tv_usec))
+		if (fin_time >= statement_fin_time)
 			return true;
 	}
 	else
@@ -1225,16 +1229,14 @@ disable_sig_alarm(bool is_statement_timeout)
 static bool
 CheckStatementTimeout(void)
 {
-	struct timeval now;
+	TimestampTz now;
 
 	if (!statement_timeout_active)
 		return true;			/* do nothing if not active */
 
-	gettimeofday(&now, NULL);
+	now = GetCurrentTimestamp();
 
-	if (now.tv_sec > statement_fin_time.tv_sec ||
-		(now.tv_sec == statement_fin_time.tv_sec &&
-		 now.tv_usec >= statement_fin_time.tv_usec))
+	if (now >= statement_fin_time)
 	{
 		/* Time to die */
 		statement_timeout_active = false;
@@ -1244,16 +1246,21 @@ CheckStatementTimeout(void)
 	else
 	{
 		/* Not time yet, so (re)schedule the interrupt */
+		long		secs;
+		int			usecs;
 		struct itimerval timeval;
 
+		TimestampDifference(now, statement_fin_time,
+							&secs, &usecs);
+		/*
+		 * It's possible that the difference is less than a microsecond;
+		 * ensure we don't cancel, rather than set, the interrupt.
+		 */
+		if (secs == 0 && usecs == 0)
+			usecs = 1;
 		MemSet(&timeval, 0, sizeof(struct itimerval));
-		timeval.it_value.tv_sec = statement_fin_time.tv_sec - now.tv_sec;
-		timeval.it_value.tv_usec = statement_fin_time.tv_usec - now.tv_usec;
-		if (timeval.it_value.tv_usec < 0)
-		{
-			timeval.it_value.tv_sec--;
-			timeval.it_value.tv_usec += 1000000;
-		}
+		timeval.it_value.tv_sec = secs;
+		timeval.it_value.tv_usec = usecs;
 		if (setitimer(ITIMER_REAL, &timeval, NULL))
 			return false;
 	}

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
@@ -118,12 +118,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
@@ -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,45 +1070,43 @@ 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))
+		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.%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,
+						(errmsg("duration: %ld.%03d ms  statement: %s%s",
+								secs, msecs,
 								query_string,
 								prepare_string ? prepare_string : "")));
 		}
+	}
 
 	if (save_log_statement_stats)
 		ShowUsage("QUERY STATISTICS");
@@ -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,46 +1800,44 @@ 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))
+		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.%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>",
+						(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)
 		ShowUsage("QUERY STATISTICS");
@@ -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,7 +3071,6 @@ 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)));
 }

src/backend/utils/adt/timestamp.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.163 2006/04/25 00:25:18 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.164 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -963,6 +963,39 @@ GetCurrentTimestamp(void)
 	return result;
 }
 
+/*
+ * TimestampDifference -- convert the difference between two timestamps
+ *		into integer seconds and microseconds
+ *
+ * Both inputs must be ordinary finite timestamps (in current usage,
+ * they'll be results from GetCurrentTimestamp()).
+ *
+ * We expect start_time <= stop_time.  If not, we return zeroes; for current
+ * callers there is no need to be tense about which way division rounds on
+ * negative inputs.
+ */
+void
+TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
+					long *secs, int *microsecs)
+{
+	TimestampTz diff = stop_time - start_time;
+
+	if (diff <= 0)
+	{
+		*secs = 0;
+		*microsecs = 0;
+	}
+	else
+	{
+#ifdef HAVE_INT64_TIMESTAMP
+		*secs = (long) (diff / USECS_PER_SEC);
+		*microsecs = (int) (diff % USECS_PER_SEC);
+#else
+		*secs = (long) diff;
+		*microsecs = (int) ((diff - *secs) * 1000000.0);
+#endif
+	}
+}
 
 /*
  * Convert a time_t to TimestampTz.
@@ -985,6 +1018,27 @@ time_t_to_timestamptz(time_t tm)
 	return result;
 }
 
+/*
+ * Convert a TimestampTz to time_t.
+ *
+ * This too is just marginally useful, but some places need it.
+ */
+time_t
+timestamptz_to_time_t(TimestampTz t)
+{
+	time_t		result;
+
+#ifdef HAVE_INT64_TIMESTAMP
+	result = (time_t) (t / USECS_PER_SEC +
+		((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY));
+#else
+	result = (time_t) (t +
+		((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY));
+#endif
+
+	return result;
+}
+
 
 void
 dt2time(Timestamp jd, int *hour, int *min, int *sec, fsec_t *fsec)

src/backend/utils/error/elog.c

@@ -42,7 +42,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.169 2006/03/05 15:58:46 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/error/elog.c,v 1.170 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1408,7 +1408,7 @@ log_line_prefix(StringInfo buf)
 				if (MyProcPort)
 				{
 					appendStringInfo(buf, "%lx.%x",
-								   (long) (MyProcPort->session_start.tv_sec),
+									 (long) (MyProcPort->session_start),
 									 MyProcPid);
 				}
 				break;
@@ -1440,7 +1440,7 @@ log_line_prefix(StringInfo buf)
 
 					strftime(strfbuf, sizeof(strfbuf),
 					/* leave room for milliseconds... */
-					/* Win32 timezone names are too long so don't print them. */
+					/* Win32 timezone names are too long so don't print them */
 #ifndef WIN32
 							 "%Y-%m-%d %H:%M:%S     %Z",
 #else
@@ -1474,12 +1474,11 @@ log_line_prefix(StringInfo buf)
 			case 's':
 				if (MyProcPort)
 				{
-					time_t		stamp_time = MyProcPort->session_start.tv_sec;
 					char		strfbuf[128];
 
 					strftime(strfbuf, sizeof(strfbuf),
 							 "%Y-%m-%d %H:%M:%S %Z",
-							 localtime(&stamp_time));
+							 localtime(&MyProcPort->session_start));
 					appendStringInfoString(buf, strfbuf);
 				}
 				break;

src/backend/utils/mmgr/portalmem.c

@@ -12,7 +12,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.87 2006/04/25 14:11:58 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.88 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -202,7 +202,7 @@ CreatePortal(const char *name, bool allowDup, bool dupSilent)
 	portal->atStart = true;
 	portal->atEnd = true;		/* disallow fetches until query is set */
 	portal->visible = true;
-	portal->creation_time = GetCurrentTimestamp();
+	portal->creation_time = GetCurrentStatementStartTimestamp();
 
 	/* put portal in table (sets portal->name) */
 	PortalHashTableInsert(portal, name);

src/include/libpq/libpq-be.h

@@ -11,7 +11,7 @@
  * Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/libpq/libpq-be.h,v 1.55 2006/03/05 15:58:56 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/libpq/libpq-be.h,v 1.56 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -31,6 +31,7 @@
 
 #include "libpq/hba.h"
 #include "libpq/pqcomm.h"
+#include "utils/timestamp.h"
 
 
 typedef enum CAC_state
@@ -80,7 +81,8 @@ typedef struct Port
 	 * but since it gets used by elog.c in the same way as database_name and
 	 * other members of this struct, we may as well keep it here.
 	 */
-	struct timeval session_start;		/* for session duration logging */
+	TimestampTz	SessionStartTime;	/* backend start time */
+	time_t		session_start;		/* same, in time_t format */
 
 	/*
 	 * TCP keepalive settings.
@@ -97,7 +99,8 @@ typedef struct Port
 	int			keepalives_count;
 
 	/*
-	 * SSL structures
+	 * SSL structures (keep these last so that USE_SSL doesn't affect
+	 * locations of other fields)
 	 */
 #ifdef USE_SSL
 	SSL		   *ssl;

src/include/utils/timestamp.h

@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.60 2006/04/25 00:25:22 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.61 2006/06/20 22:52:00 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -177,6 +177,12 @@ typedef double fsec_t;
 #define INTERVAL_PRECISION(t) ((t) & INTERVAL_PRECISION_MASK)
 #define INTERVAL_RANGE(t) (((t) >> 16) & INTERVAL_RANGE_MASK)
 
+#ifdef HAVE_INT64_TIMESTAMP
+#define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) * 1000))
+#else
+#define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) / 1000.0))
+#endif
+
 
 /* Set at postmaster start */
 extern TimestampTz PgStartTime;
@@ -293,7 +299,11 @@ extern Datum pgsql_postmaster_start_time(PG_FUNCTION_ARGS);
 
 extern TimestampTz GetCurrentTimestamp(void);
 
+extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
+								long *secs, int *microsecs);
+
 extern TimestampTz time_t_to_timestamptz(time_t tm);
+extern time_t timestamptz_to_time_t(TimestampTz t);
 
 extern int	tm2timestamp(struct pg_tm * tm, fsec_t fsec, int *tzp, Timestamp *dt);
 extern int timestamp2tm(Timestamp dt, int *tzp, struct pg_tm * tm,