Index: postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.442
diff -d -c -r1.442 postgres.c
*** postgres.c	22 Feb 2005 04:37:17 -0000	1.442
--- postgres.c	11 Apr 2005 21:10:44 -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)
***************
*** 1580,1585 ****
--- 1581,1592 ----
  	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;
  	if (dest == Remote)
***************
*** 1615,1620 ****
--- 1622,1648 ----
  
  	set_ps_display(portal->commandTag);
  
+ 	/* ...using similar logic to exec_simple_query
+ 	 * 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 ((log_statement == LOGSTMT_ALL && save_log_duration) || 
+             save_log_min_duration_statement)
+ 		gettimeofday(&start_t, NULL);
+ 
+ 	if (save_log_statement_stats)
+ 		ResetUsage();
+ 
+ 	statement_logged = false;
+ 	if (log_statement == LOGSTMT_ALL)
+ 	{
+ 		ereport(LOG,
+ 				(errmsg("statement: %s", debug_query_string)));
+ 		statement_logged = true;
+ 	}
+ 
  	BeginCommand(portal->commandTag, dest);
  
  	/* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1737,1784 ----
  			pq_putemptymessage('s');
  	}
  
+     /* ...using similar logic to exec_simple_query
+ 	 * 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: %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,
+ 							debug_query_string)));
+ 	}
+ 
+ 	if (save_log_statement_stats)
+ 		ShowUsage("QUERY STATISTICS");
  	debug_query_string = NULL;
  }