Tom Lane wrote:
> Alvaro Herrera <[EMAIL PROTECTED]> writes:
> > Alvaro Herrera wrote:
> >> Tom Lane wrote:
> >>> BTW, shouldn't the log entry distinguish whether this was VACUUM,
> >>> ANALYZE, or both?
> >>
> >> We don't actually log anything for ANALYZE (the logging code is in
> >> lazy_vacuum_rel).
> >>
> >> Maybe it should be in autovacuum.c.
>
> Actually, I had misunderstood where you were proposing to put this.
> I believe that where you have it, the elapsed-time indication will
> only cover the VACUUM step; so it's not relevant to this code whether
> an ANALYZE would happen too.
Correct.
> My suggestion is that you add similar but independent logging to
> analyze.c, controlled by the same min-duration variable. So the
> log output would treat autovac and autoanalyze as two independently
> loggable operations. I don't think there's much to print about
> an autoanalyze except its runtime ... well, maybe you could print
> the numbers of rows sampled and estimated, but I dunno if it matters.
> The point of doing it is just to be able to track what the heck
> autovacuum is doing ...
Seems fair. Updated patch attached.
If there are no further comments, I'll add some docs and apply it later.
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Index: src/backend/commands/analyze.c
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/commands/analyze.c,v
retrieving revision 1.104
diff -c -p -r1.104 analyze.c
*** src/backend/commands/analyze.c 6 Apr 2007 04:21:42 -0000 1.104
--- src/backend/commands/analyze.c 17 Apr 2007 22:52:26 -0000
***************
*** 22,27 ****
--- 22,28 ----
#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,38 ****
--- 30,41 ----
#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"
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 109,114 ****
--- 112,119 ----
double totalrows,
totaldeadrows;
HeapTuple *rows;
+ PGRUsage ru0;
+ TimestampTz starttime = 0;
if (vacstmt->verbose)
elevel = INFO;
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 190,195 ****
--- 195,204 ----
return;
}
+ /* measure elapsed time iff autovacuum logging requires it */
+ if (IsAutoVacuumWorkerProcess() && Log_autovacuum > 0)
+ starttime = GetCurrentTimestamp();
+
ereport(elevel,
(errmsg("analyzing \"%s.%s\"",
get_namespace_name(RelationGetNamespace(onerel)),
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 451,456 ****
--- 460,493 ----
* 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))));
+ }
+ }
}
/*
Index: src/backend/commands/vacuumlazy.c
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/commands/vacuumlazy.c,v
retrieving revision 1.85
diff -c -p -r1.85 vacuumlazy.c
*** src/backend/commands/vacuumlazy.c 21 Feb 2007 22:47:45 -0000 1.85
--- src/backend/commands/vacuumlazy.c 17 Apr 2007 20:08:00 -0000
***************
*** 47,55 ****
--- 47,57 ----
#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"
*************** typedef struct LVRelStats
*** 90,95 ****
--- 92,98 ----
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;
*************** lazy_vacuum_rel(Relation onerel, VacuumS
*** 141,146 ****
--- 144,157 ----
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;
*************** lazy_vacuum_rel(Relation onerel, VacuumS
*** 156,161 ****
--- 167,174 ----
/* 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);
*************** lazy_vacuum_rel(Relation onerel, VacuumS
*** 200,205 ****
--- 213,252 ----
/* 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))));
+ }
+ }
}
*************** lazy_scan_heap(Relation onerel, LVRelSta
*** 282,287 ****
--- 329,335 ----
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);
*************** lazy_scan_heap(Relation onerel, LVRelSta
*** 490,495 ****
--- 538,544 ----
vacrelstats);
/* Remove tuples from heap */
lazy_vacuum_heap(onerel, vacrelstats);
+ vacrelstats->num_index_scans++;
}
/* Do post-vacuum cleanup and statistics update for each index */
Index: src/backend/postmaster/autovacuum.c
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.41
diff -c -p -r1.41 autovacuum.c
*** src/backend/postmaster/autovacuum.c 16 Apr 2007 18:29:52 -0000 1.41
--- src/backend/postmaster/autovacuum.c 17 Apr 2007 20:06:00 -0000
*************** int autovacuum_freeze_max_age;
*** 71,76 ****
--- 71,78 ----
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;
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.385
diff -c -p -r1.385 guc.c
*** src/backend/utils/misc/guc.c 16 Apr 2007 18:29:55 -0000 1.385
--- src/backend/utils/misc/guc.c 17 Apr 2007 20:05:15 -0000
*************** static struct config_int ConfigureNamesI
*** 1506,1511 ****
--- 1506,1522 ----
},
{
+ {"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."),
NULL,
Index: src/include/postmaster/autovacuum.h
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/include/postmaster/autovacuum.h,v
retrieving revision 1.9
diff -c -p -r1.9 autovacuum.h
*** src/include/postmaster/autovacuum.h 16 Apr 2007 18:30:03 -0000 1.9
--- src/include/postmaster/autovacuum.h 17 Apr 2007 20:08:17 -0000
*************** extern int autovacuum_vac_cost_limit;
*** 31,36 ****
--- 31,38 ----
/* 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);
---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?
http://archives.postgresql.org
