Subject: log_autovacuum

From: "Simon Riggs" <[email-masked]>
Date: Thu, 08 Mar 2007 16:05:48 +0000

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

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

---

From: Neil Conway <[email-masked]>
Date: Thu, 08 Mar 2007 12:52:49 -0500

> 0.00s/0.00u sec elapsed 0.39 sec

Seems like a pretty cryptic log format to me.

-Neil

---

From: Alvaro Herrera <[email-masked]>
Date: Thu, 8 Mar 2007 14:53:30 -0300

> 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

---

From: Darcy Buskermolen <[email-masked]>
Date: Thu, 8 Mar 2007 10:03:23 -0800

On March 8, 2007 09:53 am, Alvaro Herrera wrote:
> 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 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/

---

From: Alvaro Herrera <[email-masked]>
Date: Thu, 8 Mar 2007 15:13:07 -0300

> 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.

---

From: "Simon Riggs" <[email-masked]>
Date: Thu, 08 Mar 2007 18:31:36 +0000

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:
>  Maybe something like this is better:
> 

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.

--- src/backend/commands/vacuumlazy.c	8 Mar 2007 18:27:45 -0000

***************
*** 141,146 ****
--- 143,151 ----
  	Relation   *Irel;
  	int			nindexes;
  
  	if (vacstmt->verbose)
  		elevel = INFO;
***************
*** 156,161 ****
--- 161,168 ----
  
+ 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 ----

--- src/backend/postmaster/autovacuum.c	8 Mar 2007 18:27:45 -0000
  
--- src/backend/utils/misc/guc.c	8 Mar 2007 18:27:48 -0000
--- src/include/postmaster/autovacuum.h	8 Mar 2007 18:27:52 -0000

---

From: NikhilS <[email-masked]>
Date: Fri, 9 Mar 2007 11:59:17 +0530

Hi,

> 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

---

From: Bruce Momjian <[email-masked]>
Date: Thu, 22 Mar 2007 17:59:34 -0400 (EDT)

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.

---------------------------------------------------------------------------

> understand that better than I.

[ Attachment, skipping... ]

> 
> ---------------------------(end of broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
>        subscribe-nomail command to [email-masked] so that your
>        message can get through to the mailing list cleanly

-- 
  Bruce Momjian  <[email-masked]>          http://momjian.us
  EnterpriseDB                               http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 14:06:33 -0400

> 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.

---

From: "Simon Riggs" <[email-masked]>
Date: Tue, 17 Apr 2007 19:25:14 +0100

>         system usage: CPU 0.29s/0.38u sec elapsed 2.56 sec

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

---

From: Tom Lane <[email-masked]>
Date: Tue, 17 Apr 2007 14:36:01 -0400

>         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

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 14:38:33 -0400

> their descriptions.  "x removed, y remain" might work.

Fixed.

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 14:45:50 -0400

> 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?

> >         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
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_scan_heap(Relation onerel, LVRelSta
--- 514,520 ----
  
  	/* 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;

---

From: Tom Lane <[email-masked]>
Date: Tue, 17 Apr 2007 14:59:16 -0400

> 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

---

From: "Simon Riggs" <[email-masked]>
Date: Tue, 17 Apr 2007 20:01:57 +0100

> 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

> time?  Also, why do it by time and not by amount of tuples/pages

...because you only want to know about slow vacuums.

Time is a more natural unit than tuples removed.

---

From: Bill Moran <[email-masked]>
Date: Tue, 17 Apr 2007 15:10:04 -0400

> time?  Also, why do it by time and not by amount of tuples/pages

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-masked]
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.
****************************************************************

---

From: Tom Lane <[email-masked]>
Date: Tue, 17 Apr 2007 16:19:04 -0400

BTW, shouldn't the log entry distinguish whether this was VACUUM,
ANALYZE, or both?

			regards, tom lane

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 16:41:09 -0400

> BTW, shouldn't the log entry distinguish whether this was VACUUM,

We don't actually log anything for ANALYZE (the logging code is in
lazy_vacuum_rel).

Maybe it should be in autovacuum.c.

---

From: "Simon Riggs" <[email-masked]>
Date: Tue, 17 Apr 2007 21:48:48 +0100

> We don't actually log anything for ANALYZE (the logging code is in

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.

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 18:18:04 -0400

> 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?

--- src/backend/commands/vacuumlazy.c	17 Apr 2007 20:08:00 -0000

*************** 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;
--- 167,174 ----
  
+ 	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))));
+ 		}
+ 	}
  }

--- 329,335 ----
  
--- 538,544 ----
  
--- src/backend/postmaster/autovacuum.c	17 Apr 2007 20:06:00 -0000
  
+ 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);

---

From: Tom Lane <[email-masked]>
Date: Tue, 17 Apr 2007 18:32:26 -0400

>> 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

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 18:57:49 -0400

> an ANALYZE would happen too.

Correct.

> The point of doing it is just to be able to track what the heck

Seems fair.  Updated patch attached.

If there are no further comments, I'll add some docs and apply it later.

-- 
Alvaro Herrera                                http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
Index: src/backend/commands/analyze.c
===================================================================
RCS file: /home/alvherre/Code/cvs/pgsql/src/backend/commands/analyze.c,v
retrieving revision 1.104
diff -c -p -r1.104 analyze.c
*** src/backend/commands/analyze.c	6 Apr 2007 04:21:42 -0000	1.104
--- src/backend/commands/analyze.c	17 Apr 2007 22:52:26 -0000
***************
*** 22,27 ****
--- 22,28 ----
  #include "catalog/index.h"
  #include "catalog/indexing.h"
  #include "catalog/namespace.h"
+ #include "commands/dbcommands.h"
  #include "commands/vacuum.h"
  #include "executor/executor.h"
  #include "miscadmin.h"
***************
*** 29,38 ****
--- 30,41 ----
  #include "parser/parse_oper.h"
  #include "parser/parse_relation.h"
  #include "pgstat.h"
+ #include "postmaster/autovacuum.h"
  #include "utils/acl.h"
  #include "utils/datum.h"
  #include "utils/lsyscache.h"
  #include "utils/memutils.h"
+ #include "utils/pg_rusage.h"
  #include "utils/syscache.h"
  #include "utils/tuplesort.h"
  
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 109,114 ****
--- 112,119 ----
  	double		totalrows,
  				totaldeadrows;
  	HeapTuple  *rows;
+ 	PGRUsage	ru0;
+ 	TimestampTz	starttime = 0;
  
  	if (vacstmt->verbose)
  		elevel = INFO;
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 190,195 ****
--- 195,204 ----
  		return;
  	}
  
+ 	/* measure elapsed time iff autovacuum logging requires it */
+ 	if (IsAutoVacuumWorkerProcess() && Log_autovacuum > 0)
+ 		starttime = GetCurrentTimestamp();
+ 
  	ereport(elevel,
  			(errmsg("analyzing \"%s.%s\"",
  					get_namespace_name(RelationGetNamespace(onerel)),
*************** analyze_rel(Oid relid, VacuumStmt *vacst
*** 451,456 ****
--- 460,493 ----
  	 * expose us to concurrent-update failures in update_attstats.)
  	 */
  	relation_close(onerel, NoLock);
+ 
+ 	/* Log the action if appropriate */
+ 	if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
+ 	{
+ 		long	diff;
+ 
+ 		if (Log_autovacuum > 0)
+ 		{
+ 			TimestampTz	endtime;
+ 			int		usecs;
+ 			long	secs;
+ 
+ 			endtime = GetCurrentTimestamp();
+ 			TimestampDifference(starttime, endtime, &secs, &usecs);
+ 
+ 			diff = secs * 1000 + usecs / 1000;
+ 		}
+ 		
+ 		if (Log_autovacuum == 0 || diff >= Log_autovacuum)
+ 		{
+ 			ereport(LOG,
+ 					(errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s",
+ 							get_database_name(MyDatabaseId),
+ 							get_namespace_name(RelationGetNamespace(onerel)),
+ 							RelationGetRelationName(onerel),
+ 							pg_rusage_show(&ru0))));
+ 		}
+ 	}
  }
  
  /*

  	if (vacstmt->verbose)
  		elevel = INFO;

  

  
  	{

---

From: Alvaro Herrera <[email-masked]>
Date: Tue, 17 Apr 2007 21:45:27 -0400

> 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

---

From: Tom Lane <[email-masked]>
Date: Wed, 18 Apr 2007 00:59:55 -0400

> DEBUG:  autovac: will ANALYZE bar

+1, those were just ad-hoc.

			regards, tom lane

---

From: "Simon Riggs" <[email-masked]>
Date: Wed, 18 Apr 2007 08:14:42 +0100

> DEBUG:  autovac: will ANALYZE bar

Looks good.

---

From: Alvaro Herrera <[email-masked]>
Date: Wed, 18 Apr 2007 16:46:48 -0400

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-masked]...Done

-- 
Alvaro Herrera                                http://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 -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"

  	if (vacstmt->verbose)
  		elevel = INFO;
--- 195,208 ----
  		return;
  	}
  
--- 464,497 ----
  
  /*
--- src/backend/commands/vacuumlazy.c	18 Apr 2007 15:54:53 -0000

  	if (vacstmt->verbose)
  		elevel = INFO;

  
  
--- src/backend/postmaster/autovacuum.c	18 Apr 2007 15:54:53 -0000
  
+ 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 ----
--- src/backend/utils/misc/guc.c	18 Apr 2007 15:54:53 -0000
  
  	{
+ 		{"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;

---

From: Alvaro Herrera <[email-masked]>
Date: Wed, 18 Apr 2007 17:55:17 -0400

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í"

---

From: "Marc G. Fournier" <[email-masked]>
Date: Wed, 18 Apr 2007 19:25:24 -0300

With your @alvh.no-ip.org address?

> pgsql-patches and pgsql-committers?

- ----
Marc G. Fournier           Hub.Org Networking Services (http://www.hub.org)
Email . [email-masked]                              MSN . [email-masked]
Yahoo . yscrappy               Skype: hub.org        ICQ . 7615664

---

From: Alvaro Herrera <[email-masked]>
Date: Wed, 18 Apr 2007 18:28:21 -0400

> 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.