Implement rate-limiting logic on how often backends will attempt to send

messages to the stats collector.  This avoids the problem that enabling
stats_row_level for autovacuum has a significant overhead for short
read-only transactions, as noted by Arjen van der Meijden.  We can avoid
an extra gettimeofday call by piggybacking on the one done for WAL-logging
xact commit or abort (although that doesn't help read-only transactions,
since they don't WAL-log anything).

In my proposal for this, I noted that we could change the WAL log entries
for commit/abort to record full TimestampTz precision, instead of only
time_t as at present.  That's not done in this patch, but will be committed
separately.

Author: tglsfdc

src/backend/access/transam/xact.c

@@ -10,7 +10,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.240 2007/04/26 23:24:44 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.241 2007/04/30 03:23:48 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -160,11 +160,13 @@ static CommandId currentCommandId;
 /*
  * xactStartTimestamp is the value of transaction_timestamp().
  * stmtStartTimestamp is the value of statement_timestamp().
+ * xactStopTimestamp is the time at which we log a commit or abort WAL record.
  * 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;
+static TimestampTz xactStopTimestamp;
 
 /*
  * GID to be used for preparing the current transaction.  This is also
@@ -435,6 +437,20 @@ GetCurrentStatementStartTimestamp(void)
 	return stmtStartTimestamp;
 }
 
+/*
+ *	GetCurrentTransactionStopTimestamp
+ *
+ * We return current time if the transaction stop time hasn't been set
+ * (which can happen if we decide we don't need to log an XLOG record).
+ */
+TimestampTz
+GetCurrentTransactionStopTimestamp(void)
+{
+	if (xactStopTimestamp != 0)
+		return xactStopTimestamp;
+	return GetCurrentTimestamp();
+}
+
 /*
  *	SetCurrentStatementStartTimestamp
  */
@@ -444,6 +460,15 @@ SetCurrentStatementStartTimestamp(void)
 	stmtStartTimestamp = GetCurrentTimestamp();
 }
 
+/*
+ *	SetCurrentTransactionStopTimestamp
+ */
+static inline void
+SetCurrentTransactionStopTimestamp(void)
+{
+	xactStopTimestamp = GetCurrentTimestamp();
+}
+
 /*
  *	GetCurrentTransactionNestLevel
  *
@@ -747,7 +772,8 @@ RecordTransactionCommit(void)
 			 */
 			MyProc->inCommit = true;
 
-			xlrec.xtime = time(NULL);
+			SetCurrentTransactionStopTimestamp();
+			xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp);
 			xlrec.nrels = nrels;
 			xlrec.nsubxacts = nchildren;
 			rdata[0].data = (char *) (&xlrec);
@@ -1042,7 +1068,8 @@ RecordTransactionAbort(void)
 			xl_xact_abort xlrec;
 			XLogRecPtr	recptr;
 
-			xlrec.xtime = time(NULL);
+			SetCurrentTransactionStopTimestamp();
+			xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp);
 			xlrec.nrels = nrels;
 			xlrec.nsubxacts = nchildren;
 			rdata[0].data = (char *) (&xlrec);
@@ -1415,9 +1442,11 @@ StartTransaction(void)
 	/*
 	 * 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).
+	 * GetCurrentTimestamp() call (which'd be expensive anyway).  Also,
+	 * mark xactStopTimestamp as unset.
 	 */
 	xactStartTimestamp = stmtStartTimestamp;
+	xactStopTimestamp = 0;
 	pgstat_report_txn_timestamp(xactStartTimestamp);
 
 	/*

src/backend/commands/analyze.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.106 2007/04/19 16:26:44 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.107 2007/04/30 03:23:48 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -468,29 +468,15 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt)
 	/* Log the action if appropriate */
 	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
 	{
-		long	diff = 0L;
-
-		if (Log_autovacuum > 0)
-		{
-			TimestampTz	endtime;
-			int		usecs;
-			long	secs;
-
-			endtime = GetCurrentTimestamp();
-			TimestampDifference(starttime, endtime, &secs, &usecs);
-
-			diff = secs * 1000 + usecs / 1000;
-		}
-		
-		if (Log_autovacuum == 0 || diff >= Log_autovacuum)
-		{
+		if (Log_autovacuum == 0 ||
+			TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(),
+									   Log_autovacuum))
 			ereport(LOG,
 					(errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s",
 							get_database_name(MyDatabaseId),
 							get_namespace_name(RelationGetNamespace(onerel)),
 							RelationGetRelationName(onerel),
 							pg_rusage_show(&ru0))));
-		}
 	}
 }
 

src/backend/commands/vacuumlazy.c

@@ -36,7 +36,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.87 2007/04/19 16:26:44 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.88 2007/04/30 03:23:48 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -217,22 +217,9 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
 	/* and log the action if appropriate */
 	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
 	{
-		long	diff = 0L;
-
-		if (Log_autovacuum > 0)
-		{
-			TimestampTz	endtime;
-			int		usecs;
-			long	secs;
-
-			endtime = GetCurrentTimestamp();
-			TimestampDifference(starttime, endtime, &secs, &usecs);
-
-			diff = secs * 1000 + usecs / 1000;
-		}
-		
-		if (Log_autovacuum == 0 || diff >= Log_autovacuum)
-		{
+		if (Log_autovacuum == 0 ||
+			TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(),
+									   Log_autovacuum))
 			ereport(LOG,
 					(errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n"
 							"pages: %d removed, %d remain\n"
@@ -245,7 +232,6 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
 							vacrelstats->pages_removed, vacrelstats->rel_pages,
 							vacrelstats->tuples_deleted, vacrelstats->rel_tuples, 
 							pg_rusage_show(&ru0))));
-		}
 	}
 }
 

src/backend/postmaster/pgstat.c

@@ -13,7 +13,7 @@
  *
  *	Copyright (c) 2001-2007, PostgreSQL Global Development Group
  *
- *	$PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.153 2007/04/21 04:10:53 tgl Exp $
+ *	$PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.154 2007/04/30 03:23:49 tgl Exp $
  * ----------
  */
 #include "postgres.h"
@@ -608,15 +608,34 @@ void allow_immediate_pgstat_restart(void)
 /* ----------
  * pgstat_report_tabstat() -
  *
- *	Called from tcop/postgres.c to send the so far collected
- *	per table access statistics to the collector.
+ *	Called from tcop/postgres.c to send the so far collected per-table
+ *	access statistics to the collector.  Note that this is called only
+ *	when not within a transaction, so it is fair to use transaction stop
+ *	time as an approximation of current time.
  * ----------
  */
 void
 pgstat_report_tabstat(void)
 {
+	static TimestampTz last_report = 0;	
+	TimestampTz now;
+
+	/* Don't expend a clock check if nothing to do */
+	if (RegularTabStat.tsa_used == 0 &&
+		SharedTabStat.tsa_used == 0)
+		return;
+
+	/*
+	 * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL
+	 * msec since we last sent one.
+	 */
+	now = GetCurrentTransactionStopTimestamp();
+	if (!TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL))
+		return;
+	last_report = now;
+
 	/*
-	 * For each message buffer used during the last query set the header
+	 * For each message buffer used during the last queries, set the header
 	 * fields and send it out; then mark the entries unused.
 	 */
 	pgstat_report_one_tabstat(&RegularTabStat, MyDatabaseId);

src/backend/utils/adt/timestamp.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.174 2007/02/27 23:48:09 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.175 2007/04/30 03:23:49 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1238,6 +1238,27 @@ TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
 	}
 }
 
+/*
+ * TimestampDifferenceExceeds -- report whether the difference between two
+ *		timestamps is >= a threshold (expressed in milliseconds)
+ *
+ * Both inputs must be ordinary finite timestamps (in current usage,
+ * they'll be results from GetCurrentTimestamp()).
+ */
+bool
+TimestampDifferenceExceeds(TimestampTz start_time,
+						   TimestampTz stop_time,
+						   int msec)
+{
+	TimestampTz diff = stop_time - start_time;
+
+#ifdef HAVE_INT64_TIMESTAMP
+	return (diff >= msec * INT64CONST(1000));
+#else
+	return (diff * 1000.0 >= msec);
+#endif
+}
+
 /*
  * Convert a time_t to TimestampTz.
  *

src/include/access/xact.h

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/access/xact.h,v 1.85 2007/03/13 00:33:42 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/access/xact.h,v 1.86 2007/04/30 03:23:49 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -142,6 +142,7 @@ extern SubTransactionId GetCurrentSubTransactionId(void);
 extern CommandId GetCurrentCommandId(void);
 extern TimestampTz GetCurrentTransactionStartTimestamp(void);
 extern TimestampTz GetCurrentStatementStartTimestamp(void);
+extern TimestampTz GetCurrentTransactionStopTimestamp(void);
 extern void SetCurrentStatementStartTimestamp(void);
 extern int	GetCurrentTransactionNestLevel(void);
 extern bool TransactionIdIsCurrentTransactionId(TransactionId xid);

src/include/utils/timestamp.h

@@ -6,7 +6,7 @@
  * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.67 2007/02/16 03:39:45 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.68 2007/04/30 03:23:49 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -311,6 +311,9 @@ extern TimestampTz GetCurrentTimestamp(void);
 
 extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
 					long *secs, int *microsecs);
+extern bool TimestampDifferenceExceeds(TimestampTz start_time,
+									   TimestampTz stop_time,
+									   int msec);
 
 extern TimestampTz time_t_to_timestamptz(time_t tm);
 extern time_t timestamptz_to_time_t(TimestampTz t);

src/test/regress/expected/stats.out

@@ -73,6 +73,14 @@ SELECT count(*) FROM tenk2 WHERE unique1 = 1;
      1
 (1 row)
 
+-- force the rate-limiting logic in pgstat_report_tabstat() to time out
+-- and send a message
+SELECT pg_sleep(1.0);
+ pg_sleep 
+----------
+ 
+(1 row)
+
 -- wait for stats collector to update
 SELECT wait_for_stats();
  wait_for_stats 

src/test/regress/sql/stats.sql

@@ -60,6 +60,10 @@ SELECT count(*) FROM tenk2;
 -- do an indexscan
 SELECT count(*) FROM tenk2 WHERE unique1 = 1;
 
+-- force the rate-limiting logic in pgstat_report_tabstat() to time out
+-- and send a message
+SELECT pg_sleep(1.0);
+
 -- wait for stats collector to update
 SELECT wait_for_stats();