From ef23a77441b94d1e2fde3f359d2e49703c70c9ca Mon Sep 17 00:00:00 2001 From: Alvaro Herrera Date: Wed, 18 Apr 2007 16:44:18 +0000 Subject: [PATCH] Enable configurable log of autovacuum actions. Initial patch from Simon Riggs, additional code and docs by me. Per discussion. --- doc/src/sgml/config.sgml | 21 +++++++- src/backend/commands/analyze.c | 43 +++++++++++++++- src/backend/commands/vacuumlazy.c | 51 ++++++++++++++++++- src/backend/postmaster/autovacuum.c | 12 ++--- src/backend/utils/misc/guc.c | 13 ++++- src/backend/utils/misc/postgresql.conf.sample | 5 +- src/include/postmaster/autovacuum.h | 4 +- 7 files changed, 134 insertions(+), 15 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e10d2d753a..c5670dd906 100644 --- 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 44e743363a..f558458d77 100644 --- 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 b93288c388..4e4f6373a4 100644 --- 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 9893fa680b..d5bb99c504 100644 --- 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 83ea00c568..b9643a734d 100644 --- 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 bc5b642d02..e7d8e41b0e 100644 --- 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 ccd982b681..bc464de14a 100644 --- 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);