Enable configurable log of autovacuum actions. Initial patch from Simon

Riggs, additional code and docs by me.  Per discussion.

Author: alvherre

doc/src/sgml/config.sgml

@@ -1,4 +1,4 @@
-<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.120 2007/04/16 18:29:50 alvherre Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.121 2007/04/18 16:44:17 alvherre Exp $ -->
 
 <chapter Id="runtime-config">
   <title>Server Configuration</title>
@@ -3190,6 +3190,25 @@ SELECT * FROM parent WHERE key = 2400;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-autovacuum" xreflabel="log_autovacuum">
+      <term><varname>log_autovacuum</varname> (<type>integer</type>)</term>
+      <indexterm>
+       <primary><varname>log_autovacuum</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        Causes actions executed by autovacuum to be logged if it ran for at
+        least the specified number of milliseconds.  Setting this to zero prints
+        all action durations. Minus-one (the default) disables logging
+        autovacuum action durations.  For example, if you set it to
+        <literal>250ms</literal> then all vacuums and analyzes that run
+        250ms or longer will be logged.  Enabling this parameter can be helpful
+        in tracking autovacuum activity.  This setting can only be set in
+        the <filename>postgresql.conf</> file or on the server command line.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-autovacuum-naptime" xreflabel="autovacuum_naptime">
       <term><varname>autovacuum_naptime</varname> (<type>integer</type>)</term>
       <indexterm>

src/backend/commands/analyze.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.104 2007/04/06 04:21:42 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.105 2007/04/18 16:44:17 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -22,17 +22,20 @@
 #include "catalog/index.h"
 #include "catalog/indexing.h"
 #include "catalog/namespace.h"
+#include "commands/dbcommands.h"
 #include "commands/vacuum.h"
 #include "executor/executor.h"
 #include "miscadmin.h"
 #include "parser/parse_expr.h"
 #include "parser/parse_oper.h"
 #include "parser/parse_relation.h"
 #include "pgstat.h"
+#include "postmaster/autovacuum.h"
 #include "utils/acl.h"
 #include "utils/datum.h"
 #include "utils/lsyscache.h"
 #include "utils/memutils.h"
+#include "utils/pg_rusage.h"
 #include "utils/syscache.h"
 #include "utils/tuplesort.h"
 
@@ -109,6 +112,8 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt)
 	double		totalrows,
 				totaldeadrows;
 	HeapTuple  *rows;
+	PGRUsage	ru0;
+	TimestampTz	starttime = 0;
 
 	if (vacstmt->verbose)
 		elevel = INFO;
@@ -190,6 +195,14 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt)
 		return;
 	}
 
+	/* measure elapsed time iff autovacuum logging requires it */
+	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
+	{
+		pg_rusage_init(&ru0);
+		if (Log_autovacuum > 0)
+			starttime = GetCurrentTimestamp();
+	}
+
 	ereport(elevel,
 			(errmsg("analyzing \"%s.%s\"",
 					get_namespace_name(RelationGetNamespace(onerel)),
@@ -451,6 +464,34 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt)
 	 * expose us to concurrent-update failures in update_attstats.)
 	 */
 	relation_close(onerel, NoLock);
+
+	/* Log the action if appropriate */
+	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
+	{
+		long	diff;
+
+		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)
+		{
+			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.85 2007/02/21 22:47:45 momjian Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.86 2007/04/18 16:44:18 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -47,9 +47,11 @@
 #include "access/genam.h"
 #include "access/heapam.h"
 #include "access/transam.h"
+#include "commands/dbcommands.h"
 #include "commands/vacuum.h"
 #include "miscadmin.h"
 #include "pgstat.h"
+#include "postmaster/autovacuum.h"
 #include "storage/freespace.h"
 #include "utils/lsyscache.h"
 #include "utils/memutils.h"
@@ -90,6 +92,7 @@ typedef struct LVRelStats
 	int			max_free_pages; /* # slots allocated in array */
 	PageFreeSpaceInfo *free_pages;		/* array or heap of blkno/avail */
 	BlockNumber tot_free_pages; /* total pages with >= threshold space */
+	int			num_index_scans;
 } LVRelStats;
 
 
@@ -141,6 +144,14 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
 	Relation   *Irel;
 	int			nindexes;
 	BlockNumber possibly_freeable;
+	PGRUsage	ru0;
+	TimestampTz	starttime = 0;
+
+	pg_rusage_init(&ru0);
+
+	/* measure elapsed time iff autovacuum logging requires it */
+	if (IsAutoVacuumWorkerProcess() && Log_autovacuum > 0)
+		starttime = GetCurrentTimestamp();
 
 	if (vacstmt->verbose)
 		elevel = INFO;
@@ -156,6 +167,8 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
 	/* XXX should we scale it up or down?  Adjust vacuum.c too, if so */
 	vacrelstats->threshold = GetAvgFSMRequestSize(&onerel->rd_node);
 
+	vacrelstats->num_index_scans = 0;
+
 	/* Open all indexes of the relation */
 	vac_open_indexes(onerel, RowExclusiveLock, &nindexes, &Irel);
 	vacrelstats->hasindex = (nindexes > 0);
@@ -200,6 +213,40 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
 	/* report results to the stats collector, too */
 	pgstat_report_vacuum(RelationGetRelid(onerel), onerel->rd_rel->relisshared,
 						 vacstmt->analyze, vacrelstats->rel_tuples);
+
+	/* and log the action if appropriate */
+	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
+	{
+		long	diff;
+
+		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)
+		{
+			ereport(LOG,
+					(errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n"
+							"pages: %d removed, %d remain\n"
+							"tuples: %.0f removed, %.0f remain\n"
+							"system usage: %s",
+							get_database_name(MyDatabaseId),
+							get_namespace_name(RelationGetNamespace(onerel)),
+							RelationGetRelationName(onerel),
+							vacrelstats->num_index_scans,
+							vacrelstats->pages_removed, vacrelstats->rel_pages,
+							vacrelstats->tuples_deleted, vacrelstats->rel_tuples, 
+							pg_rusage_show(&ru0))));
+		}
+	}
 }
 
 
@@ -282,6 +329,7 @@ lazy_scan_heap(Relation onerel, LVRelStats *vacrelstats,
 			lazy_vacuum_heap(onerel, vacrelstats);
 			/* Forget the now-vacuumed tuples, and press on */
 			vacrelstats->num_dead_tuples = 0;
+			vacrelstats->num_index_scans++;
 		}
 
 		buf = ReadBuffer(onerel, blkno);
@@ -490,6 +538,7 @@ lazy_scan_heap(Relation onerel, LVRelStats *vacrelstats,
 							  vacrelstats);
 		/* Remove tuples from heap */
 		lazy_vacuum_heap(onerel, vacrelstats);
+		vacrelstats->num_index_scans++;
 	}
 
 	/* Do post-vacuum cleanup and statistics update for each index */

src/backend/postmaster/autovacuum.c

@@ -10,7 +10,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/postmaster/autovacuum.c,v 1.41 2007/04/16 18:29:52 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/postmaster/autovacuum.c,v 1.42 2007/04/18 16:44:18 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -71,6 +71,8 @@ int			autovacuum_freeze_max_age;
 int			autovacuum_vac_cost_delay;
 int			autovacuum_vac_cost_limit;
 
+int			Log_autovacuum = -1;
+
 /* Flags to tell if we are in an autovacuum process */
 static bool am_autovacuum_launcher = false;
 static bool am_autovacuum_worker = false;
@@ -1814,7 +1816,6 @@ do_autovacuum(void)
 	{
 		Oid		relid = lfirst_oid(cell);
 		autovac_table *tab;
-		char   *relname;
 		WorkerInfo	worker;
 		bool        skipit;
 
@@ -1891,12 +1892,6 @@ do_autovacuum(void)
 		VacuumCostDelay = tab->at_vacuum_cost_delay;
 		VacuumCostLimit = tab->at_vacuum_cost_limit;
 
-		relname = get_rel_name(relid);
-		elog(DEBUG2, "autovac: will%s%s %s",
-			 (tab->at_dovacuum ? " VACUUM" : ""),
-			 (tab->at_doanalyze ? " ANALYZE" : ""),
-			 relname);
-
 		/*
 		 * Advertise my cost delay parameters for the balancing algorithm, and
 		 * do a balance
@@ -1915,7 +1910,6 @@ do_autovacuum(void)
 								  tab->at_freeze_min_age);
 		/* be tidy */
 		pfree(tab);
-		pfree(relname);
 	}
 
 	/*

src/backend/utils/misc/guc.c

@@ -10,7 +10,7 @@
  * Written by Peter Eisentraut <peter_e@gmx.net>.
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.385 2007/04/16 18:29:55 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.386 2007/04/18 16:44:18 alvherre Exp $
  *
  *--------------------------------------------------------------------
  */
@@ -1505,6 +1505,17 @@ static struct config_int ConfigureNamesInt[] =
 		-1, -1, INT_MAX / 1000, NULL, NULL
 	},
 
+	{
+		{"log_autovacuum", PGC_BACKEND, LOGGING_WHAT,
+			gettext_noop("Sets the minimum execution time above which autovacuum actions "
+						 "will be logged."),
+			gettext_noop("Zero prints all actions.  The default is -1 (turning this feature off)."),
+			GUC_UNIT_MS
+		},
+		&Log_autovacuum,
+		-1, -1, INT_MAX / 1000, NULL, NULL
+	},
+
 	{
 		{"bgwriter_delay", PGC_SIGHUP, RESOURCES,
 			gettext_noop("Background writer sleep time between rounds."),

src/backend/utils/misc/postgresql.conf.sample

@@ -376,8 +376,11 @@
 #autovacuum = on			# enable autovacuum subprocess?
 					# 'on' requires stats_start_collector
 					# and stats_row_level to also be on
-#autovacuum_max_workers = 3 # max # of autovacuum subprocesses
+#autovacuum_max_workers = 3		# max # of autovacuum subprocesses
 #autovacuum_naptime = 1min		# time between autovacuum runs
+#log_autovacuum = -1			# -1 is disabled, 0 logs all actions
+					# and their durations, > 0 logs only
+					# actions running at least N msec.
 #autovacuum_vacuum_threshold = 500	# min # of tuple updates before
 					# vacuum
 #autovacuum_analyze_threshold = 250	# min # of tuple updates before 

src/include/postmaster/autovacuum.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/postmaster/autovacuum.h,v 1.9 2007/04/16 18:30:03 alvherre Exp $
+ * $PostgreSQL: pgsql/src/include/postmaster/autovacuum.h,v 1.10 2007/04/18 16:44:18 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -31,6 +31,8 @@ extern int	autovacuum_vac_cost_limit;
 /* autovacuum launcher PID, only valid when worker is shutting down */
 extern int	AutovacuumLauncherPid;
 
+extern int	Log_autovacuum;
+
 /* Status inquiry functions */
 extern bool AutoVacuumingActive(void);
 extern bool IsAutoVacuumLauncherProcess(void);