public inbox for [email protected]
help / color / mirror / Atom feedlog_autovacuum
29+ messages / 10 participants
[nested] [flat]
* log_autovacuum
@ 2007-03-08 16:05 Simon Riggs <[email protected]>
0 siblings, 2 replies; 29+ messages in thread
From: Simon Riggs @ 2007-03-08 16:05 UTC (permalink / raw)
To: [email protected]; +Cc: Alvaro Herrera <[email protected]>
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
No docs yet, but will do this if accepted.
scans: N number of times indexes have been scanned
pages: remaining(-removed)
tuples: remaining(-removed)
CPU
elapsed
--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com
Attachments:
[text/x-patch] log_autovacuum.v1.patch (4.8K, 2-log_autovacuum.v1.patch)
download | inline diff:
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 -0000 1.85
--- src/backend/commands/vacuumlazy.c 8 Mar 2007 15:51:06 -0000
***************
*** 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("autovac \"%s.%s\" scans:%d pages:%d(-%d) tuples:%.0f(-%.0f) %s",
+ get_namespace_name(RelationGetNamespace(onerel)),
+ RelationGetRelationName(onerel), vacrelstats->num_index_scans,
+ vacrelstats->rel_pages, vacrelstats->pages_removed,
+ vacrelstats->rel_tuples, vacrelstats->tuples_deleted,
+ 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 -0000 1.33
--- src/backend/postmaster/autovacuum.c 8 Mar 2007 15:51:07 -0000
***************
*** 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 -0000 1.379
--- src/backend/utils/misc/guc.c 8 Mar 2007 15:51:11 -0000
***************
*** 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,
gettext_noop("Turns on various assertion checks."),
gettext_noop("This is a debugging aid."),
Index: src/include/postmaster/autovacuum.h
===================================================================
RCS file: /projects/cvsroot/pgsql/src/include/postmaster/autovacuum.h,v
retrieving revision 1.8
diff -c -r1.8 autovacuum.h
*** src/include/postmaster/autovacuum.h 15 Feb 2007 23:23:23 -0000 1.8
--- src/include/postmaster/autovacuum.h 8 Mar 2007 15:51:18 -0000
***************
*** 25,30 ****
--- 25,32 ----
extern int autovacuum_vac_cost_delay;
extern int autovacuum_vac_cost_limit;
+ extern bool Log_autovacuum;
+
/* Status inquiry functions */
extern bool AutoVacuumingActive(void);
extern bool IsAutoVacuumLauncherProcess(void);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-08 17:52 Neil Conway <[email protected]>
parent: Simon Riggs <[email protected]>
1 sibling, 0 replies; 29+ messages in thread
From: Neil Conway @ 2007-03-08 17:52 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: [email protected]; Alvaro Herrera <[email protected]>
On Thu, 2007-03-08 at 16:05 +0000, 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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-08 17:53 Alvaro Herrera <[email protected]>
parent: Simon Riggs <[email protected]>
1 sibling, 2 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-03-08 17:53 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: [email protected]
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 Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-08 18:03 Darcy Buskermolen <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 1 reply; 29+ messages in thread
From: Darcy Buskermolen @ 2007-03-08 18:03 UTC (permalink / raw)
To: [email protected]; +Cc: Alvaro Herrera <[email protected]>; Simon Riggs <[email protected]>
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/
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-08 18:13 Alvaro Herrera <[email protected]>
parent: Darcy Buskermolen <[email protected]>
0 siblings, 0 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-03-08 18:13 UTC (permalink / raw)
To: Darcy Buskermolen <[email protected]>; +Cc: [email protected]; Simon Riggs <[email protected]>
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 Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-08 18:31 Simon Riggs <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 3 replies; 29+ messages in thread
From: Simon Riggs @ 2007-03-08 18:31 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: [email protected]
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
Attachments:
[text/x-patch] log_autovacuum.v2.patch (4.8K, 2-log_autovacuum.v2.patch)
download | inline diff:
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 -0000 1.85
--- src/backend/commands/vacuumlazy.c 8 Mar 2007 18:27:45 -0000
***************
*** 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 -0000 1.33
--- src/backend/postmaster/autovacuum.c 8 Mar 2007 18:27:45 -0000
***************
*** 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 -0000 1.379
--- src/backend/utils/misc/guc.c 8 Mar 2007 18:27:48 -0000
***************
*** 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,
gettext_noop("Turns on various assertion checks."),
gettext_noop("This is a debugging aid."),
Index: src/include/postmaster/autovacuum.h
===================================================================
RCS file: /projects/cvsroot/pgsql/src/include/postmaster/autovacuum.h,v
retrieving revision 1.8
diff -c -r1.8 autovacuum.h
*** src/include/postmaster/autovacuum.h 15 Feb 2007 23:23:23 -0000 1.8
--- src/include/postmaster/autovacuum.h 8 Mar 2007 18:27:52 -0000
***************
*** 25,30 ****
--- 25,32 ----
extern int autovacuum_vac_cost_delay;
extern int autovacuum_vac_cost_limit;
+ extern bool Log_autovacuum;
+
/* Status inquiry functions */
extern bool AutoVacuumingActive(void);
extern bool IsAutoVacuumLauncherProcess(void);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-09 06:29 NikhilS <[email protected]>
parent: Simon Riggs <[email protected]>
2 siblings, 0 replies; 29+ messages in thread
From: NikhilS @ 2007-03-09 06:29 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: Alvaro Herrera <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-03-22 21:59 Bruce Momjian <[email protected]>
parent: Simon Riggs <[email protected]>
2 siblings, 0 replies; 29+ messages in thread
From: Bruce Momjian @ 2007-03-22 21:59 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: Alvaro Herrera <[email protected]>; [email protected]
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. +
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:06 Alvaro Herrera <[email protected]>
parent: Simon Riggs <[email protected]>
2 siblings, 2 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 18:06 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: [email protected]
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 Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:25 Simon Riggs <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 1 reply; 29+ messages in thread
From: Simon Riggs @ 2007-04-17 18:25 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: [email protected]
On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote:
> 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.
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.
I guess we need to see how this interacts with HOT, as well.
Presumably you mean to have both removeds in the same order?
> pages: 0 removed, 11226 remain
> tuples: 1300683 removed, 1096236 remain
--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:36 Tom Lane <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 1 reply; 29+ messages in thread
From: Tom Lane @ 2007-04-17 18:36 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:38 Alvaro Herrera <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 0 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 18:38 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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 Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:45 Alvaro Herrera <[email protected]>
parent: Simon Riggs <[email protected]>
0 siblings, 3 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 18:45 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: [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?
> 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 Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Attachments:
[text/x-diff] log-autovacuum.patch (5.5K, 2-log-autovacuum.patch)
download | inline diff:
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 17:48:24 -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,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 -0000 1.41
--- src/backend/postmaster/autovacuum.c 17 Apr 2007 17:21:56 -0000
*************** int autovacuum_freeze_max_age;
*** 71,76 ****
--- 71,78 ----
int autovacuum_vac_cost_delay;
int autovacuum_vac_cost_limit;
+ bool Log_autovacuum = false;
+
/* 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 17:33:47 -0000
*************** static struct config_bool ConfigureNames
*** 593,598 ****
--- 593,606 ----
false, NULL, NULL
},
{
+ {"log_autovacuum", PGC_BACKEND, LOGGING_WHAT,
+ gettext_noop("Logs duration and statistics of a VACUUM run by the autovacuum daemon."),
+ NULL
+ },
+ &Log_autovacuum,
+ false, NULL, NULL
+ },
+ {
{"debug_assertions", PGC_USERSET, DEVELOPER_OPTIONS,
gettext_noop("Turns on various assertion checks."),
gettext_noop("This is a debugging aid."),
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 17:21:10 -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 bool Log_autovacuum;
+
/* Status inquiry functions */
extern bool AutoVacuumingActive(void);
extern bool IsAutoVacuumLauncherProcess(void);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 18:59 Tom Lane <[email protected]>
parent: Alvaro Herrera <[email protected]>
2 siblings, 0 replies; 29+ messages in thread
From: Tom Lane @ 2007-04-17 18:59 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 19:01 Simon Riggs <[email protected]>
parent: Alvaro Herrera <[email protected]>
2 siblings, 0 replies; 29+ messages in thread
From: Simon Riggs @ 2007-04-17 19:01 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 19:10 Bill Moran <[email protected]>
parent: Alvaro Herrera <[email protected]>
2 siblings, 1 reply; 29+ messages in thread
From: Bill Moran @ 2007-04-17 19:10 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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.
****************************************************************
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 20:19 Tom Lane <[email protected]>
parent: Bill Moran <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Tom Lane @ 2007-04-17 20:19 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
BTW, shouldn't the log entry distinguish whether this was VACUUM,
ANALYZE, or both?
regards, tom lane
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 20:41 Alvaro Herrera <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 2 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 20:41 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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 Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 20:48 Simon Riggs <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 0 replies; 29+ messages in thread
From: Simon Riggs @ 2007-04-17 20:48 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Tom Lane <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 22:18 Alvaro Herrera <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 1 reply; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 22:18 UTC (permalink / raw)
To: Tom Lane <[email protected]>; Simon Riggs <[email protected]>; [email protected]
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 Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Attachments:
[text/x-diff] log-autovacuum.patch (6.1K, 2-log-autovacuum.patch)
download | inline diff:
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);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 22:32 Tom Lane <[email protected]>
parent: Alvaro Herrera <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Tom Lane @ 2007-04-17 22:32 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-17 22:57 Alvaro Herrera <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-17 22:57 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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.
Attachments:
[text/x-diff] log-autovacuum.patch (8.6K, 2-log-autovacuum.patch)
download | inline diff:
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);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-18 01:45 Alvaro Herrera <[email protected]>
parent: Alvaro Herrera <[email protected]>
0 siblings, 2 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-18 01:45 UTC (permalink / raw)
To: Tom Lane <[email protected]>; Simon Riggs <[email protected]>; [email protected]
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, 2000097 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 Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-18 04:59 Tom Lane <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 0 replies; 29+ messages in thread
From: Tom Lane @ 2007-04-18 04:59 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Simon Riggs <[email protected]>; [email protected]
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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-18 07:14 Simon Riggs <[email protected]>
parent: Alvaro Herrera <[email protected]>
1 sibling, 1 reply; 29+ messages in thread
From: Simon Riggs @ 2007-04-18 07:14 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: Tom Lane <[email protected]>; [email protected]
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, 2000097 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
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: log_autovacuum
@ 2007-04-18 20:46 Alvaro Herrera <[email protected]>
parent: Simon Riggs <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-18 20:46 UTC (permalink / raw)
To: Simon Riggs <[email protected]>; +Cc: Tom Lane <[email protected]>; [email protected]
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 Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Attachments:
[text/x-diff] log-autovacuum.patch (12.5K, 2-log-autovacuum.patch)
download | inline diff:
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 -0000 1.120
--- doc/src/sgml/config.sgml 18 Apr 2007 15:54:53 -0000
*************** SELECT * FROM parent WHERE key = 2400;
*** 3190,3195 ****
--- 3190,3214 ----
</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>
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 18 Apr 2007 15:54:53 -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,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, VacuumStmt *vacst
*** 451,456 ****
--- 464,497 ----
* 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 18 Apr 2007 15:54:53 -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 18 Apr 2007 15:54:53 -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;
*************** do_autovacuum(void)
*** 1814,1820 ****
{
Oid relid = lfirst_oid(cell);
autovac_table *tab;
- char *relname;
WorkerInfo worker;
bool skipit;
--- 1816,1821 ----
*************** next_worker:
*** 1891,1902 ****
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
--- 1892,1897 ----
*************** next_worker:
*** 1915,1921 ****
tab->at_freeze_min_age);
/* be tidy */
pfree(tab);
- pfree(relname);
}
/*
--- 1910,1915 ----
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 18 Apr 2007 15:54:53 -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/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.214
diff -c -p -r1.214 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 16 Apr 2007 18:29:55 -0000 1.214
--- src/backend/utils/misc/postgresql.conf.sample 18 Apr 2007 15:54:53 -0000
***************
*** 376,383 ****
#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_naptime = 1min # time between autovacuum runs
#autovacuum_vacuum_threshold = 500 # min # of tuple updates before
# vacuum
#autovacuum_analyze_threshold = 250 # min # of tuple updates before
--- 376,386 ----
#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_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
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 18 Apr 2007 15:54:53 -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);
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: [PATCHES] log_autovacuum
@ 2007-04-18 21:55 Alvaro Herrera <[email protected]>
parent: Alvaro Herrera <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-18 21:55 UTC (permalink / raw)
To: Marc G. Fournier <[email protected]>; +Cc: pgsql-www
Marc G. Fournier wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> There were a couple stuck, put them all through ..
Hmm. Could you please add me as moderator for pgsql-hackers,
pgsql-patches and pgsql-committers?
Thanks
--
Alvaro Herrera http://www.flickr.com/photos/alvherre/
"La verdad no siempre es bonita, pero el hambre de ella sí"
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: [PATCHES] log_autovacuum
@ 2007-04-18 22:25 Marc G. Fournier <[email protected]>
parent: Alvaro Herrera <[email protected]>
0 siblings, 1 reply; 29+ messages in thread
From: Marc G. Fournier @ 2007-04-18 22:25 UTC (permalink / raw)
To: Alvaro Herrera <[email protected]>; +Cc: pgsql-www
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
With your @alvh.no-ip.org address?
- --On Wednesday, April 18, 2007 17:55:17 -0400 Alvaro Herrera
<[email protected]> wrote:
> Marc G. Fournier wrote:
>> -----BEGIN PGP SIGNED MESSAGE-----
>> Hash: SHA1
>>
>> There were a couple stuck, put them all through ..
>
> Hmm. Could you please add me as moderator for pgsql-hackers,
> pgsql-patches and pgsql-committers?
>
> Thanks
>
> --
> Alvaro Herrera http://www.flickr.com/photos/alvherre/
> "La verdad no siempre es bonita, pero el hambre de ella sí"
- ----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email . [email protected] MSN . [email protected]
Yahoo . yscrappy Skype: hub.org ICQ . 7615664
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.5 (FreeBSD)
iD8DBQFGJprU4QvfyHIvDvMRAlq+AJ9LoOvm49VSKttJUM0rxY/7lVdlXQCfVbPi
krq1QzRluzQdWk27VdKR/rA=
=z4ZJ
-----END PGP SIGNATURE-----
^ permalink raw reply [nested|flat] 29+ messages in thread
* Re: [PATCHES] log_autovacuum
@ 2007-04-18 22:28 Alvaro Herrera <[email protected]>
parent: Marc G. Fournier <[email protected]>
0 siblings, 0 replies; 29+ messages in thread
From: Alvaro Herrera @ 2007-04-18 22:28 UTC (permalink / raw)
To: Marc G. Fournier <[email protected]>; +Cc: pgsql-www
Marc G. Fournier wrote:
> With your @alvh.no-ip.org address?
Yes, this is my primary address (and the one with which I'm subscribed).
The other is just an alias.
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 29+ messages in thread
end of thread, other threads:[~2007-04-18 22:28 UTC | newest]
Thread overview: 29+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2007-03-08 16:05 log_autovacuum Simon Riggs <[email protected]>
2007-03-08 17:52 ` Neil Conway <[email protected]>
2007-03-08 17:53 ` Alvaro Herrera <[email protected]>
2007-03-08 18:03 ` Darcy Buskermolen <[email protected]>
2007-03-08 18:13 ` Alvaro Herrera <[email protected]>
2007-03-08 18:31 ` Simon Riggs <[email protected]>
2007-03-09 06:29 ` NikhilS <[email protected]>
2007-03-22 21:59 ` Bruce Momjian <[email protected]>
2007-04-17 18:06 ` Alvaro Herrera <[email protected]>
2007-04-17 18:25 ` Simon Riggs <[email protected]>
2007-04-17 18:45 ` Alvaro Herrera <[email protected]>
2007-04-17 18:59 ` Tom Lane <[email protected]>
2007-04-17 19:01 ` Simon Riggs <[email protected]>
2007-04-17 19:10 ` Bill Moran <[email protected]>
2007-04-17 20:19 ` Tom Lane <[email protected]>
2007-04-17 20:41 ` Alvaro Herrera <[email protected]>
2007-04-17 20:48 ` Simon Riggs <[email protected]>
2007-04-17 22:18 ` Alvaro Herrera <[email protected]>
2007-04-17 22:32 ` Tom Lane <[email protected]>
2007-04-17 22:57 ` Alvaro Herrera <[email protected]>
2007-04-18 01:45 ` Alvaro Herrera <[email protected]>
2007-04-18 04:59 ` Tom Lane <[email protected]>
2007-04-18 07:14 ` Simon Riggs <[email protected]>
2007-04-18 20:46 ` Alvaro Herrera <[email protected]>
2007-04-18 21:55 ` Alvaro Herrera <[email protected]>
2007-04-18 22:25 ` Marc G. Fournier <[email protected]>
2007-04-18 22:28 ` Alvaro Herrera <[email protected]>
2007-04-17 18:36 ` Tom Lane <[email protected]>
2007-04-17 18:38 ` Alvaro Herrera <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox