Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c	21 Apr 2005 19:18:13 -0000	1.443
--- src/backend/tcop/postgres.c	16 May 2005 03:40:00 -0000
***************
*** 1011,1017 ****
  			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 (statement_logged && save_log_duration)
--- 1011,1018 ----
  			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 (statement_logged && save_log_duration)
***************
*** 1579,1584 ****
--- 1580,1590 ----
  	bool		is_trans_exit = false;
  	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;
  
  	/* Adjust destination to tell printtup.c what to do */
  	dest = whereToSendOutput;
***************
*** 1615,1620 ****
--- 1621,1648 ----
  
  	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.
+ 	 */
+ 	if (save_log_duration || save_log_min_duration_statement != -1)
+ 		gettimeofday(&start_t, NULL);
+ 
+ 	if (save_log_statement_stats)
+ 		ResetUsage();
+ 
+ 	statement_logged = false;
+ 	if (log_statement == LOGSTMT_ALL)
+ 	{
+ 		/* We have the portal, so output the source query. */
+ 		ereport(LOG,
+ 				(errmsg("statement: EXECUTE %s  [PREPARE:  %s]", portal_name,
+ 						portal->sourceText ? portal->sourceText : "")));
+ 		statement_logged = true;
+ 	}
+ 
  	BeginCommand(portal->commandTag, dest);
  
  	/* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1737,1786 ----
  			pq_putemptymessage('s');
  	}
  
+ 	/*
+ 	 * Combine processing here as we need to calculate the query duration
+ 	 * in both instances.
+ 	 */
+ 	if (save_log_duration || save_log_min_duration_statement != -1)
+ 	{
+ 		long		usecs;
+ 
+ 		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 (statement_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)));
+ 
+ 		/*
+ 		 * Output a duration_statement to the log if the query has
+ 		 * exceeded the min duration, or if we are to print all durations.
+ 		 */
+ 		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: EXECUTE %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,
+ 							portal_name,
+ 							portal->sourceText ? portal->sourceText : "")));
+ 	}
+ 
+ 	if (save_log_statement_stats)
+ 		ShowUsage("QUERY STATISTICS");
+ 
  	debug_query_string = NULL;
  }