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 @@
-
+
 
 
   Server Configuration
@@ -3190,6 +3190,25 @@ SELECT * FROM parent WHERE key = 2400;
       
      
 
+     
+      log_autovacuum (integer)
+      
+       log_autovacuum configuration parameter
+      
+      
+       
+        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
+        250ms 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 postgresql.conf file or on the server command line.
+       
+      
+     
+
      
       autovacuum_naptime (integer)
       

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 .
  *
  * 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);