Enable configurable log of autovacuum actions. Initial patch from Simon

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

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e10d2d753a37ca21561d7ad20a8eaf1e0f43a58e..c5670dd906b5895735f1bcaa7b4af0f4676d2613 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/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>

diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index 44e743363ad135d57eccf964162c41c5bd2535bd..f558458d778bbc438e029db4094292cbde7e5a3a 100644 (file)
--- a/src/backend/commands/analyze.c
+++ b/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,6 +22,7 @@
 #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"
@@ -29,10 +30,12 @@
 #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))));
+               }
+       }
 }
 
 /*

diff --git a/src/backend/commands/vacuumlazy.c b/src/backend/commands/vacuumlazy.c
index b93288c388b60f56e7f08c8ac4f33539095c4e29..4e4f6373a46fd7434de2dcd411b9b65116203796 100644 (file)
--- a/src/backend/commands/vacuumlazy.c
+++ b/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 */

diff --git a/src/backend/postmaster/autovacuum.c b/src/backend/postmaster/autovacuum.c
index 9893fa680b7a6ac79f61bab8e1bdec6e4d32ca2b..d5bb99c504ba01af072288ca1a66b84c402fa760 100644 (file)
--- a/src/backend/postmaster/autovacuum.c
+++ b/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 @@ next_worker:
                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 @@ next_worker:
                                                                  tab->at_freeze_min_age);
                /* be tidy */
                pfree(tab);
-               pfree(relname);
        }
 
        /*

diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 83ea00c568a51cf2b00bb23588c8ff4a1228d96d..b9643a734d30425d8906ed80bd6bb108c3a5d4b3 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/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."),

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index bc5b642d0298a80f0eb9abb4f3a5765cf193f4e1..e7d8e41b0e1432f8254a17c47674318bf5c649d0 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/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 

diff --git a/src/include/postmaster/autovacuum.h b/src/include/postmaster/autovacuum.h
index ccd982b6814d25af363eab898bd7a1d78583034d..bc464de14af12f296f7cdc486930e45b81ef6cf8 100644 (file)
--- a/src/include/postmaster/autovacuum.h
+++ b/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);