Re: [PATCHES] log_autovacuum
On Tue, 2007-04-17 at 21:45 -0400, Alvaro Herrera wrote: Alvaro Herrera wrote: Seems fair. Updated patch attached. If there are no further comments, I'll add some docs and apply it later. If autovacuum_vacuum_cost_delay is set to 20, my pitiful desktop system takes 8.4 seconds to analyze a 8000 page table: DEBUG: bar: scanned 3000 of 8811 pages, containing 681000 live rows and 0 dead rows; 3000 rows in sample, 297 estimated total rows LOG: automatic analyze of table alvherre.public.bar system usage: CPU 0.00s/0.01u sec elapsed 8.39 sec So I guess logging on ANALYZE is not that removed from reality. I also think we should remove these DEBUG messages, that are now useless: DEBUG: autovac: will ANALYZE bar Looks good. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PATCHES] log_autovacuum
I applied this patch some hours ago but I haven't gotten the
pgsql-committers mail and I don't see it in the archives either. Here
is the evidence:
http://developer.postgresql.org/cvsweb.cgi/pgsql/doc/src/sgml/config.sgml
Is there a problem with pgsql-committers again? Attached is the patch I
applied.
$ cvs commit -F msg
? msg
? cscope.out
? cscope.files
Checking in doc/src/sgml/config.sgml;
/cvsroot/pgsql/doc/src/sgml/config.sgml,v -- config.sgml
new revision: 1.121; previous revision: 1.120
done
Checking in src/backend/commands/analyze.c;
/cvsroot/pgsql/src/backend/commands/analyze.c,v -- analyze.c
new revision: 1.105; previous revision: 1.104
done
Checking in src/backend/commands/vacuumlazy.c;
/cvsroot/pgsql/src/backend/commands/vacuumlazy.c,v -- vacuumlazy.c
new revision: 1.86; previous revision: 1.85
done
Checking in src/backend/postmaster/autovacuum.c;
/cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v -- autovacuum.c
new revision: 1.42; previous revision: 1.41
done
Checking in src/backend/utils/misc/guc.c;
/cvsroot/pgsql/src/backend/utils/misc/guc.c,v -- guc.c
new revision: 1.386; previous revision: 1.385
done
Checking in src/backend/utils/misc/postgresql.conf.sample;
/cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v --
postgresql.conf.sample
new revision: 1.215; previous revision: 1.214
done
Checking in src/include/postmaster/autovacuum.h;
/cvsroot/pgsql/src/include/postmaster/autovacuum.h,v -- autovacuum.h
new revision: 1.10; previous revision: 1.9
done
Collecting file lists...Done.
Sending mail to [EMAIL PROTECTED]
--
Alvaro Herrerahttp://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Index: doc/src/sgml/config.sgml
===
RCS file: /home/alvherre/Code/cvs/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.120
diff -c -p -r1.120 config.sgml
*** doc/src/sgml/config.sgml 16 Apr 2007 18:29:50 - 1.120
--- doc/src/sgml/config.sgml 18 Apr 2007 15:54:53 -
*** SELECT * FROM parent WHERE key = 2400;
*** 3190,3195
--- 3190,3214
/listitem
/varlistentry
+ varlistentry id=guc-log-autovacuum xreflabel=log_autovacuum
+ termvarnamelog_autovacuum/varname (typeinteger/type)/term
+ indexterm
+primaryvarnamelog_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
+ literal250ms/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 filenamepostgresql.conf/ file or on the server command line.
+/para
+ /listitem
+ /varlistentry
+
varlistentry id=guc-autovacuum-naptime xreflabel=autovacuum_naptime
termvarnameautovacuum_naptime/varname (typeinteger/type)/term
indexterm
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 - 1.104
--- src/backend/commands/analyze.c 18 Apr 2007 15:54:53 -
***
*** 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,208
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)),
*** analyze_rel(Oid relid,
Re: [PATCHES] log_autovacuum
Simon Riggs wrote: On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote: Maybe something like this is better: LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever CONTEXT: Automatic vacuuming of table database.public.w Yours is better. I've implemented this: LOG: autovac public.w index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever I'm happy if this gets removed later, but I think it will help everybody understand how multi-vacuums are working and what the best way to specify the controls should be. Not sure about the CONTEXT bit. I think its verbose, plus I thought that was for ERRORs only. I will defer on this point, since I know y'all understand that better than I. I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please comment. -- Alvaro Herrerahttp://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PATCHES] log_autovacuum
Alvaro Herrera [EMAIL PROTECTED] writes: I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please be a bit more consistent about whether numbers precede or follow their descriptions. x removed, y remain might work. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] log_autovacuum
Tom Lane wrote: Alvaro Herrera [EMAIL PROTECTED] writes: I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please be a bit more consistent about whether numbers precede or follow their descriptions. x removed, y remain might work. Fixed. -- Alvaro Herrerahttp://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PATCHES] log_autovacuum
Simon Riggs wrote: On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote: I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please comment. Well, 'tis great except when you have very very frequent autovacuums. That was why I wanted it in 1 log line. Perhaps we need this as an integer, so we can log all vacuums that last for longer in seconds than the setting, 0 logs all. That would significantly reduce the volume if we set it to 5, say. That way you would get your readability and I would get my reasonable size logs. It kinda smells funny to have a setting like that. Do we have a precedent? If other people is OK with it, I'll do that. Would it work to add a separate GUC var to control the minimum autovac time? Also, why do it by time and not by amount of tuples/pages removed? Presumably you mean to have both removeds in the same order? pages: 0 removed, 11226 remain tuples: 1300683 removed, 1096236 remain Right, fixed. Also, here is the patch. -- Alvaro Herrerahttp://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support 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 - 1.85 --- src/backend/commands/vacuumlazy.c 17 Apr 2007 17:48:24 - *** *** 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,152 Relation *Irel; int nindexes; BlockNumber possibly_freeable; + PGRUsage ru0; + + pg_rusage_init(ru0); if (vacstmt-verbose) elevel = INFO; *** lazy_vacuum_rel(Relation onerel, VacuumS *** 156,161 --- 162,169 /* 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 --- 208,228 /* 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 (Log_autovacuum IsAutoVacuumWorkerProcess()) + ereport(LOG, + (errmsg(automatic vacuum of table \%s.%s.%s\: index scans: %d\n + pages: removed %d, %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 --- 305,311 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 --- 514,520 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 - 1.41 --- src/backend/postmaster/autovacuum.c 17 Apr 2007
Re: [PATCHES] log_autovacuum
Alvaro Herrera [EMAIL PROTECTED] writes: Simon Riggs wrote: Perhaps we need this as an integer, so we can log all vacuums that last for longer in seconds than the setting, 0 logs all. That would significantly reduce the volume if we set it to 5, say. That way you would get your readability and I would get my reasonable size logs. It kinda smells funny to have a setting like that. Do we have a precedent? If other people is OK with it, I'll do that. Sure, log_min_duration_statement. Applying the same concept to autovac logging makes sense to me. In fact, what you've got now is equivalent to an unconditional log_statement boolean, which is about where we were three or four releases ago on statement logging. History suggests that we'd soon want it to be more flexible than that. It seems sane to me to skip the boolean stage and go straight to a threshold parameter. Also, why do it by time and not by amount of tuples/pages removed? One, it's consistent with the way we do thresholded statement logging. Two, time is a better indicator of effort expended --- consider vacuuming a very large table that has only a few dead tuples. We might want to add logging thresholds for pages/tuples later, but for now I'd vote for just one parameter: a time threshold. regards, tom lane ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PATCHES] log_autovacuum
On Tue, 2007-04-17 at 14:45 -0400, Alvaro Herrera wrote: Simon Riggs wrote: On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote: I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please comment. Well, 'tis great except when you have very very frequent autovacuums. That was why I wanted it in 1 log line. Perhaps we need this as an integer, so we can log all vacuums that last for longer in seconds than the setting, 0 logs all. That would significantly reduce the volume if we set it to 5, say. That way you would get your readability and I would get my reasonable size logs. It kinda smells funny to have a setting like that. Do we have a precedent? If other people is OK with it, I'll do that. log_temp_files works a bit like that, as does log_min_duration_statement perhaps log_min_duration_vacuum? that would be easier to understand Would it work to add a separate GUC var to control the minimum autovac time? Also, why do it by time and not by amount of tuples/pages removed? ...because you only want to know about slow vacuums. Time is a more natural unit than tuples removed. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PATCHES] log_autovacuum
In response to Alvaro Herrera [EMAIL PROTECTED]: Simon Riggs wrote: On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote: I've tinkered with this patch a bit. Sample output: LOG: automatic vacuum of table alvherre.public.foo: index scans: 0 pages: removed 0, 11226 remain tuples: 1300683 removed, 1096236 remain system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec Please comment. Well, 'tis great except when you have very very frequent autovacuums. That was why I wanted it in 1 log line. Perhaps we need this as an integer, so we can log all vacuums that last for longer in seconds than the setting, 0 logs all. That would significantly reduce the volume if we set it to 5, say. That way you would get your readability and I would get my reasonable size logs. It kinda smells funny to have a setting like that. Do we have a precedent? If other people is OK with it, I'll do that. Would it work to add a separate GUC var to control the minimum autovac time? Also, why do it by time and not by amount of tuples/pages removed? When I submitted the log_temp_files stuff, there was considerable discussion on the topic of how the GUC vars should be done. IIRC, the eventual decision was to have a single GUC var, where -1 equated to off, 0 equated to log all, and numbers higher than 0 were a size limit on when things get logged. -- Bill Moran Collaborative Fusion Inc. http://people.collaborativefusion.com/~wmoran/ [EMAIL PROTECTED] Phone: 412-422-3463x4023 IMPORTANT: This message contains confidential information and is intended only for the individual named. If the reader of this message is not an intended recipient (or the individual responsible for the delivery of this message to an intended recipient), please be advised that any re-use, dissemination, distribution or copying of this message is prohibited. Please notify the sender immediately by e-mail if you have received this e-mail by mistake and delete this e-mail from your system. E-mail transmission cannot be guaranteed to be secure or error-free as information could be intercepted, corrupted, lost, destroyed, arrive late or incomplete, or contain viruses. The sender therefore does not accept liability for any errors or omissions in the contents of this message, which arise as a result of e-mail transmission. ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] log_autovacuum
BTW, shouldn't the log entry distinguish whether this was VACUUM, ANALYZE, or both? regards, tom lane ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] log_autovacuum
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. -- Alvaro Herrerahttp://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc. ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] log_autovacuum
On Tue, 2007-04-17 at 16:41 -0400, 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). When ANALYZE starts taking some time, we can log it. Maybe it should be in autovacuum.c. Well, I figured if it was the right place for VACUUM it was good enough for autovacuum too. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] log_autovacuum
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.
The only problem with this is that we would have to export struct
LVRelStats definition from vacuumlazy.c and pass the struct back ...
which wouldn't directly work on ANALYZE. What we could do is pass back
a void * pointer, which lazyvacuum.c or the analyze code knows how to
turn into a string.
I have no problem both ways. Here is the current patch (logging code
still in lazy_vacuum_rel, log_autovacuum morphed into an integer
variable).
Opinions?
--
Alvaro Herrerahttp://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
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 - 1.85
--- src/backend/commands/vacuumlazy.c 17 Apr 2007 20:08:00 -
***
*** 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 - 1.41
--- src/backend/postmaster/autovacuum.c 17 Apr 2007
Re: [PATCHES] log_autovacuum
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. 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 ... regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] log_autovacuum
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 Herrerahttp://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 - 1.104
--- src/backend/commands/analyze.c 17 Apr 2007 22:52:26 -
***
*** 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 - 1.85
--- src/backend/commands/vacuumlazy.c 17 Apr 2007 20:08:00 -
***
*** 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
Re: [PATCHES] log_autovacuum
Alvaro Herrera wrote: Seems fair. Updated patch attached. If there are no further comments, I'll add some docs and apply it later. If autovacuum_vacuum_cost_delay is set to 20, my pitiful desktop system takes 8.4 seconds to analyze a 8000 page table: DEBUG: bar: scanned 3000 of 8811 pages, containing 681000 live rows and 0 dead rows; 3000 rows in sample, 297 estimated total rows LOG: automatic analyze of table alvherre.public.bar system usage: CPU 0.00s/0.01u sec elapsed 8.39 sec So I guess logging on ANALYZE is not that removed from reality. I also think we should remove these DEBUG messages, that are now useless: DEBUG: autovac: will ANALYZE bar -- Alvaro Herrerahttp://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc. ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] log_autovacuum
Alvaro Herrera [EMAIL PROTECTED] writes: I also think we should remove these DEBUG messages, that are now useless: DEBUG: autovac: will ANALYZE bar +1, those were just ad-hoc. regards, tom lane ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PATCHES] log_autovacuum
Your patch has been added to the PostgreSQL unapplied patches list at: http://momjian.postgresql.org/cgi-bin/pgpatches It will be applied as soon as one of the PostgreSQL committers reviews and approves it. --- Simon Riggs wrote: On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote: Maybe something like this is better: LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever CONTEXT: Automatic vacuuming of table database.public.w Yours is better. I've implemented this: LOG: autovac public.w index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever I'm happy if this gets removed later, but I think it will help everybody understand how multi-vacuums are working and what the best way to specify the controls should be. Not sure about the CONTEXT bit. I think its verbose, plus I thought that was for ERRORs only. I will defer on this point, since I know y'all understand that better than I. -- Simon Riggs EnterpriseDB http://www.enterprisedb.com [ Attachment, skipping... ] ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly -- Bruce Momjian [EMAIL PROTECTED] http://momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. + ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] log_autovacuum
On Thu, 2007-03-08 at 16:05 +, Simon Riggs wrote: LOG: autovac public.w scans:1 pages:197(-0) tuples:2338(-7199) CPU 0.00s/0.00u sec elapsed 0.39 sec Seems like a pretty cryptic log format to me. -Neil ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PATCHES] log_autovacuum
Simon Riggs wrote: log_autovacuum = on produces a single line of output from autovacuum, with additional useful stats. Patch is proving useful in performance testing. Not sure what is intended on logging for 8.3 LOG: autovac public.w scans:1 pages:197(-0) tuples:2338(-7199) CPU 0.00s/0.00u sec elapsed 0.39 sec LOG: autovac public.s scans:1 pages:1926746(-0) tuples:37000611(-3461867) CPU 99.74s/53.37u sec elapsed 7977.20 sec I agree something like this is useful, but I'd try to get rid of cryptic notation, and maybe split in several message categories if reasonable. Your proposal is LOG: autovac public.w scans:1 pages:197(-0) tuples:2338(-7199) CPU 0.00s/0.00u sec elapsed 0.39 sec This looks too much like the old VACUUM VERBOSE reporting, which was awful. Maybe something like this is better: LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever CONTEXT: Automatic vacuuming of table database.public.w This looks like the sort of thing comparable to picking a bikeshed color though :-( Keep in mind that it's going to be translated, so it's not useful for machine parsing anyway. -- Alvaro Herrerahttp://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PATCHES] log_autovacuum
On March 8, 2007 09:53 am, Alvaro Herrera wrote: Simon Riggs wrote: log_autovacuum = on produces a single line of output from autovacuum, with additional useful stats. Patch is proving useful in performance testing. Not sure what is intended on logging for 8.3 LOG: autovac public.w scans:1 pages:197(-0) tuples:2338(-7199) CPU 0.00s/0.00u sec elapsed 0.39 sec LOG: autovac public.s scans:1 pages:1926746(-0) tuples:37000611(-3461867) CPU 99.74s/53.37u sec elapsed 7977.20 sec I agree something like this is useful, but I'd try to get rid of cryptic notation, and maybe split in several message categories if reasonable. Your proposal is LOG: autovac public.w scans:1 pages:197(-0) tuples:2338(-7199) CPU 0.00s/0.00u sec elapsed 0.39 sec This looks too much like the old VACUUM VERBOSE reporting, which was awful. Maybe something like this is better: LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever CONTEXT: Automatic vacuuming of table database.public.w This looks like the sort of thing comparable to picking a bikeshed color though :-( Keep in mind that it's going to be translated, so it's not useful for machine parsing anyway. This goes back to the request for vacuum loging to a table.. -- Darcy Buskermolen Command Prompt, Inc. Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240 PostgreSQL solutions since 1997 http://www.commandprompt.com/ ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PATCHES] log_autovacuum
Darcy Buskermolen wrote: On March 8, 2007 09:53 am, Alvaro Herrera wrote: Keep in mind that it's going to be translated, so it's not useful for machine parsing anyway. This goes back to the request for vacuum loging to a table.. That's right, but please let's have at least *something*. -- Alvaro Herrerahttp://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc. ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] log_autovacuum
On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:
Maybe something like this is better:
LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199,
2338 remain CPU usage: whatever
CONTEXT: Automatic vacuuming of table database.public.w
Yours is better.
I've implemented this:
LOG: autovac public.w index passes: 1 pages: removed 0, 197 remain
tuples: removed 7199, 2338 remain CPU usage: whatever
I'm happy if this gets removed later, but I think it will help everybody
understand how multi-vacuums are working and what the best way to
specify the controls should be.
Not sure about the CONTEXT bit. I think its verbose, plus I thought that
was for ERRORs only. I will defer on this point, since I know y'all
understand that better than I.
--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com
Index: src/backend/commands/vacuumlazy.c
===
RCS file: /projects/cvsroot/pgsql/src/backend/commands/vacuumlazy.c,v
retrieving revision 1.85
diff -c -r1.85 vacuumlazy.c
*** src/backend/commands/vacuumlazy.c 21 Feb 2007 22:47:45 - 1.85
--- src/backend/commands/vacuumlazy.c 8 Mar 2007 18:27:45 -
***
*** 49,54
--- 49,55
#include access/transam.h
#include commands/vacuum.h
#include miscadmin.h
+ #include postmaster/autovacuum.h
#include pgstat.h
#include storage/freespace.h
#include utils/lsyscache.h
***
*** 90,95
--- 91,97
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; /* number of scans of index */
} LVRelStats;
***
*** 141,146
--- 143,151
Relation *Irel;
int nindexes;
BlockNumber possibly_freeable;
+ PGRUsage ru0;
+
+ pg_rusage_init(ru0);
if (vacstmt-verbose)
elevel = INFO;
***
*** 156,161
--- 161,168
/* 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,205
--- 207,220
/* report results to the stats collector, too */
pgstat_report_vacuum(RelationGetRelid(onerel), onerel-rd_rel-relisshared,
vacstmt-analyze, vacrelstats-rel_tuples);
+ if (Log_autovacuum IsAutoVacuumProcess())
+ ereport(LOG,
+ (errmsg(autovacuum \%s.%s.%s\ index scans:%d pages: removed %d, %d remain tuples:%.0f removed, -%.0f remain %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,287
--- 297,303
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,495
--- 506,512
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: /projects/cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.33
diff -c -r1.33 autovacuum.c
*** src/backend/postmaster/autovacuum.c 7 Mar 2007 13:35:02 - 1.33
--- src/backend/postmaster/autovacuum.c 8 Mar 2007 18:27:45 -
***
*** 69,74
--- 69,76
int autovacuum_vac_cost_delay;
int autovacuum_vac_cost_limit;
+ bool Log_autovacuum = false;
+
/* Flag to tell if we are in the autovacuum daemon process */
static bool am_autovacuum_launcher = false;
static bool am_autovacuum_worker = false;
Index: src/backend/utils/misc/guc.c
===
RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.379
diff -c -r1.379 guc.c
*** src/backend/utils/misc/guc.c 6 Mar 2007 02:06:14 - 1.379
--- src/backend/utils/misc/guc.c 8 Mar 2007 18:27:48 -
***
*** 584,589
--- 584,597
false, NULL, NULL
},
{
+ {log_autovacuum, PGC_BACKEND, LOGGING_WHAT,
+ gettext_noop(Logs end of a session, including duration.),
+ NULL
+ },
+ Log_autovacuum,
+ false, NULL, NULL
+ },
+ {
{debug_assertions, PGC_USERSET, DEVELOPER_OPTIONS,
Re: [PATCHES] log_autovacuum
Hi, On 3/9/07, Simon Riggs [EMAIL PROTECTED] wrote: On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote: Maybe something like this is better: LOG: index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever CONTEXT: Automatic vacuuming of table database.public.w Yours is better. I've implemented this: LOG: autovac public.w index passes: 1 pages: removed 0, 197 remain tuples: removed 7199, 2338 remain CPU usage: whatever I'm happy if this gets removed later, but I think it will help everybody understand how multi-vacuums are working and what the best way to specify the controls should be. Not sure about the CONTEXT bit. I think its verbose, plus I thought that was for ERRORs only. I will defer on this point, since I know y'all understand that better than I. IMHO, it would be good to have both the messages spit out. The earlier message is much better for parsing and the later makes READABLE sense. Regards, Nikhils -- EnterpriseDB http://www.enterprisedb.com
