Re: [GENERAL] Autovacuum Logging

Is there a reason many of the most useful autovacuum.c elog
statements are set to DEBUG2? It seems to me that these should be
set to LOG.

I used autovacuum when it was a contrib module, and it failed after a
month. To prevent major performance problems I went back to the
daily vacuum. I was looking forward to using autovacuum in 8.1 since
it is more resilient and configurable now, but when I noticed it
would not log it's activities I almost decided against it. After
looking at the source code it seems that all the necessary logging is
built in, it's just not set to the appropriate log level. I'm sure
I'm not the only person interested in this, and I saw somewhere (I
can't find it again) that EnterpriseDB has enabled autovacuum
logging. I don't think it's too verbose to change these to the
normal log level, but if so could it be a postgresql.conf option to
enable/disable autovacuum logging? It sure would be nice to be able
to verify that tables are being vacuumed properly without having to
set the log level to DEBUG2.

Will Reese -- http://blog.rezra.com

I found where I saw that EnterpriseDB has enabled autovacuum logging.
Look at item number one under the section entitled "Changes in
2006-03-31 update:"

http://www.enterprisedb.com/readme_dbserver.do

Will Reese -- http://blog.rezra.com

On Apr 26, 2006, at 10:47 PM, Will Reese wrote:

> Is there a reason many of the most useful autovacuum.c elog
> statements are set to DEBUG2? It seems to me that these should be
> set to LOG.
>
> I used autovacuum when it was a contrib module, and it failed after
> a month. To prevent major performance problems I went back to the
> daily vacuum. I was looking forward to using autovacuum in 8.1
> since it is more resilient and configurable now, but when I noticed
> it would not log it's activities I almost decided against it.
> After looking at the source code it seems that all the necessary
> logging is built in, it's just not set to the appropriate log
> level. I'm sure I'm not the only person interested in this, and I
> saw somewhere (I can't find it again) that EnterpriseDB has enabled
> autovacuum logging. I don't think it's too verbose to change these
> to the normal log level, but if so could it be a postgresql.conf
> option to enable/disable autovacuum logging? It sure would be nice
> to be able to verify that tables are being vacuumed properly
> without having to set the log level to DEBUG2.
>
> Will Reese -- http://blog.rezra.com
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 6: explain analyze is your friend

I believe 8.2 will have improved autovac logging. Take a look in the
-hackers archives for more info.

On Wed, Apr 26, 2006 at 10:47:26PM -0500, Will Reese wrote:
> Is there a reason many of the most useful autovacuum.c elog
> statements are set to DEBUG2? It seems to me that these should be
> set to LOG.
>
> I used autovacuum when it was a contrib module, and it failed after a
> month. To prevent major performance problems I went back to the
> daily vacuum. I was looking forward to using autovacuum in 8.1 since
> it is more resilient and configurable now, but when I noticed it
> would not log it's activities I almost decided against it. After
> looking at the source code it seems that all the necessary logging is
> built in, it's just not set to the appropriate log level. I'm sure
> I'm not the only person interested in this, and I saw somewhere (I
> can't find it again) that EnterpriseDB has enabled autovacuum
> logging. I don't think it's too verbose to change these to the
> normal log level, but if so could it be a postgresql.conf option to
> enable/disable autovacuum logging? It sure would be nice to be able
> to verify that tables are being vacuumed properly without having to
> set the log level to DEBUG2.
>
> Will Reese -- http://blog.rezra.com
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

I found this short discussion between Tom and Bruce, but that's about
it for autovacuum logging.

http://archives.postgresql.org/pgsql-general/2006-04/msg00489.php

It just seems like the "processing database" log statement should be
set to a lower level, since it just logs every time autovacuum runs.
And the "vacuum table" log statement should be set to LOG since it
will only log when it actually vacuums a table, which is very useful
and important information. If Bruce's solution is implemented in 8.2
that would be nice, but raising the log level from DEBUG2 to LOG
would be a nice patch for 8.1.4 in the meantime. :)

Will Reese -- http://blog.rezra.com

On Apr 27, 2006, at 12:20 AM, Jim C. Nasby wrote:

> I believe 8.2 will have improved autovac logging. Take a look in the
> -hackers archives for more info.
>
> On Wed, Apr 26, 2006 at 10:47:26PM -0500, Will Reese wrote:
>> Is there a reason many of the most useful autovacuum.c elog
>> statements are set to DEBUG2? It seems to me that these should be
>> set to LOG.
>>
>> I used autovacuum when it was a contrib module, and it failed after a
>> month. To prevent major performance problems I went back to the
>> daily vacuum. I was looking forward to using autovacuum in 8.1 since
>> it is more resilient and configurable now, but when I noticed it
>> would not log it's activities I almost decided against it. After
>> looking at the source code it seems that all the necessary logging is
>> built in, it's just not set to the appropriate log level. I'm sure
>> I'm not the only person interested in this, and I saw somewhere (I
>> can't find it again) that EnterpriseDB has enabled autovacuum
>> logging. I don't think it's too verbose to change these to the
>> normal log level, but if so could it be a postgresql.conf option to
>> enable/disable autovacuum logging? It sure would be nice to be able
>> to verify that tables are being vacuumed properly without having to
>> set the log level to DEBUG2.
>>
>> Will Reese -- http://blog.rezra.com
>>
>> ---------------------------(end of
>> broadcast)---------------------------
>> TIP 6: explain analyze is your friend
>>
>
> --
> Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
> Pervasive Software http://pervasive.com work: 512-231-6117
> vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461

Right, I think there has been discussion about this and general
agreement that the current autovacuum logging options are less than
ideal to put it mildly. Unfortunately, I don't think there has been any
action by anyone to do something about it. I hope to work on this at
some point, but coding time for PG scarce resource in my life, so no
promises.

Matt

Will Reese wrote:
> I found this short discussion between Tom and Bruce, but that's about it
> for autovacuum logging.
>
> http://archives.postgresql.org/pgsql-general/2006-04/msg00489.php
>
> It just seems like the "processing database" log statement should be set
> to a lower level, since it just logs every time autovacuum runs. And
> the "vacuum table" log statement should be set to LOG since it will only
> log when it actually vacuums a table, which is very useful and important
> information. If Bruce's solution is implemented in 8.2 that would be
> nice, but raising the log level from DEBUG2 to LOG would be a nice patch
> for 8.1.4 in the meantime. :)
>
>
> Will Reese -- http://blog.rezra.com
>
> On Apr 27, 2006, at 12:20 AM, Jim C. Nasby wrote:
>
>> I believe 8.2 will have improved autovac logging. Take a look in the
>> -hackers archives for more info.
>>
>> On Wed, Apr 26, 2006 at 10:47:26PM -0500, Will Reese wrote:
>>> Is there a reason many of the most useful autovacuum.c elog
>>> statements are set to DEBUG2? It seems to me that these should be
>>> set to LOG.
>>>
>>> I used autovacuum when it was a contrib module, and it failed after a
>>> month. To prevent major performance problems I went back to the
>>> daily vacuum. I was looking forward to using autovacuum in 8.1 since
>>> it is more resilient and configurable now, but when I noticed it
>>> would not log it's activities I almost decided against it. After
>>> looking at the source code it seems that all the necessary logging is
>>> built in, it's just not set to the appropriate log level. I'm sure
>>> I'm not the only person interested in this, and I saw somewhere (I
>>> can't find it again) that EnterpriseDB has enabled autovacuum
>>> logging. I don't think it's too verbose to change these to the
>>> normal log level, but if so could it be a postgresql.conf option to
>>> enable/disable autovacuum logging? It sure would be nice to be able
>>> to verify that tables are being vacuumed properly without having to
>>> set the log level to DEBUG2.
>>>
>>> Will Reese -- http://blog.rezra.com
>>>
>>> ---------------------------(end of broadcast)---------------------------
>>> TIP 6: explain analyze is your friend
>>>
>>
>> --Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
>> Pervasive Software http://pervasive.com work: 512-231-6117
>> vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

Well, one problem now is that everytime pg_autovacuum opens a database,
a message is placed in the logs:

LOG: autovacuum: processing database "test"
LOG: autovacuum: processing database "test"
LOG: autovacuum: processing database "test"
LOG: autovacuum: processing database "test"

This is certainly not desirable. I changed the message to DEBUG1 for
8.2 with the attached patch. I also added a sentence to the
log_min_error_messages TODO item:

* Allow log_min_messages to be specified on a per-module basis

This would allow administrators to see more detailed information from
specific sections of the backend, e.g. checkpoints, autovacuum, etc.
Another idea is to allow separate configuration files for each module,
or allow arbitrary SET commands to be passed to them.

I am thinking the new second sentence is more flexible than just making
a change for log_min_error_messages.

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

Matthew T. O'Connor wrote:
> Right, I think there has been discussion about this and general
> agreement that the current autovacuum logging options are less than
> ideal to put it mildly. Unfortunately, I don't think there has been any
> action by anyone to do something about it. I hope to work on this at
> some point, but coding time for PG scarce resource in my life, so no
> promises.
>
> Matt
>
>
>
> Will Reese wrote:
> > I found this short discussion between Tom and Bruce, but that's about it
> > for autovacuum logging.
> >
> > http://archives.postgresql.org/pgsql-general/2006-04/msg00489.php
> >
> > It just seems like the "processing database" log statement should be set
> > to a lower level, since it just logs every time autovacuum runs. And
> > the "vacuum table" log statement should be set to LOG since it will only
> > log when it actually vacuums a table, which is very useful and important
> > information. If Bruce's solution is implemented in 8.2 that would be
> > nice, but raising the log level from DEBUG2 to LOG would be a nice patch
> > for 8.1.4 in the meantime. :)
> >
> >
> > Will Reese -- http://blog.rezra.com
> >
> > On Apr 27, 2006, at 12:20 AM, Jim C. Nasby wrote:
> >
> >> I believe 8.2 will have improved autovac logging. Take a look in the
> >> -hackers archives for more info.
> >>
> >> On Wed, Apr 26, 2006 at 10:47:26PM -0500, Will Reese wrote:
> >>> Is there a reason many of the most useful autovacuum.c elog
> >>> statements are set to DEBUG2? It seems to me that these should be
> >>> set to LOG.
> >>>
> >>> I used autovacuum when it was a contrib module, and it failed after a
> >>> month. To prevent major performance problems I went back to the
> >>> daily vacuum. I was looking forward to using autovacuum in 8.1 since
> >>> it is more resilient and configurable now, but when I noticed it
> >>> would not log it's activities I almost decided against it. After
> >>> looking at the source code it seems that all the necessary logging is
> >>> built in, it's just not set to the appropriate log level. I'm sure
> >>> I'm not the only person interested in this, and I saw somewhere (I
> >>> can't find it again) that EnterpriseDB has enabled autovacuum
> >>> logging. I don't think it's too verbose to change these to the
> >>> normal log level, but if so could it be a postgresql.conf option to
> >>> enable/disable autovacuum logging? It sure would be nice to be able
> >>> to verify that tables are being vacuumed properly without having to
> >>> set the log level to DEBUG2.
> >>>
> >>> Will Reese -- http://blog.rezra.com
> >>>
> >>> ---------------------------(end of broadcast)---------------------------
> >>> TIP 6: explain analyze is your friend
> >>>
> >>
> >> --Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
> >> Pervasive Software http://pervasive.com work: 512-231-6117
> >> vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461
> >
> >
> > ---------------------------(end of broadcast)---------------------------
> > TIP 6: explain analyze is your friend
> >
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo(at)postgresql(dot)org so that your
> message can get through to the mailing list cleanly
>

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

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

On Thursday 27 April 2006 11:59, Bruce Momjian wrote:
> Well, one problem now is that everytime pg_autovacuum opens a database,
> a message is placed in the logs:
>
> LOG: autovacuum: processing database "test"
> LOG: autovacuum: processing database "test"
> LOG: autovacuum: processing database "test"
> LOG: autovacuum: processing database "test"
>
> This is certainly not desirable. I changed the message to DEBUG1 for
> 8.2 with the attached patch.

IMHO this is less optimal, since the default installation will provide no way
for users to verify that autovacuum is running. Currently we can direct them
to look in thier log output, this way we would have to tell them to crank up
logging to DEBUG1 and then look, which will of course contain a whole lot of
other chatter at that level.

The best solution I have seen so far is the idea of a GUC to control
autovacuums chatter level. I hope we get that becuase the above will be a
regression imho.

--
Robert Treat
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL

I would like to bring up again that it would be nice if vacuum/analyze recorded the last action and stats in a table
(pg_vacuum) within each database. Then dba's can make better decisions how vacuum/analyze is working as well as
tuning the fsm guc's. This should be a real easy additions to the system. While I am wishing, why not change explain
analyze to put out the last analyze timestamp, this should tell people if the stats are old or not, I have to believe
that this info could also help the autovac process.

Jim

---------- Original Message -----------
From: Robert Treat <xzilla(at)users(dot)sourceforge(dot)net>
To: pgsql-general(at)postgresql(dot)org
Cc: Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us>, "Matthew T. O'Connor" <matthew(at)zeut(dot)net>, Will Reese <wreese(at)rackspace(dot)com>
Sent: Fri, 28 Apr 2006 15:15:05 -0400
Subject: Re: [GENERAL] Autovacuum Logging

> On Thursday 27 April 2006 11:59, Bruce Momjian wrote:
> > Well, one problem now is that everytime pg_autovacuum opens a database,
> > a message is placed in the logs:
> >
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> >
> > This is certainly not desirable. I changed the message to DEBUG1 for
> > 8.2 with the attached patch.
>
> IMHO this is less optimal, since the default installation will provide no way
> for users to verify that autovacuum is running. Currently we can direct them
> to look in thier log output, this way we would have to tell them to crank up
> logging to DEBUG1 and then look, which will of course contain a whole lot of
> other chatter at that level.
>
> The best solution I have seen so far is the idea of a GUC to control
> autovacuums chatter level. I hope we get that becuase the above will be a
> regression imho.
>
> --
> Robert Treat
> Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
------- End of Original Message -------

Robert Treat wrote:
> On Thursday 27 April 2006 11:59, Bruce Momjian wrote:
> > Well, one problem now is that everytime pg_autovacuum opens a database,
> > a message is placed in the logs:
> >
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> > LOG: autovacuum: processing database "test"
> >
> > This is certainly not desirable. I changed the message to DEBUG1 for
> > 8.2 with the attached patch.
>
> IMHO this is less optimal, since the default installation will provide no way
> for users to verify that autovacuum is running. Currently we can direct them
> to look in thier log output, this way we would have to tell them to crank up
> logging to DEBUG1 and then look, which will of course contain a whole lot of
> other chatter at that level.

Someone is working on it.

> The best solution I have seen so far is the idea of a GUC to control
> autovacuums chatter level. I hope we get that becuase the above will be a
> regression imho.

The purpose of the logs is not to show something _working_, but to
report significant events. Frankly, even with the GUC, to see it is
working you are still going to fill up the logs with activity.

What do people want to know? --- that autovacuum is running, or how
often. If it is the former, we can print something on server startup.

We don't even really log checkpoints, so logging every autovacuum seems
strange.

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

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

I am thinking, what do we want to show by default about autovacuum in
the server logs. What if we output a line the first time autovacuum
runs successfully on server start?

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

Bruce Momjian wrote:
> Robert Treat wrote:
> > On Thursday 27 April 2006 11:59, Bruce Momjian wrote:
> > > Well, one problem now is that everytime pg_autovacuum opens a database,
> > > a message is placed in the logs:
> > >
> > > LOG: autovacuum: processing database "test"
> > > LOG: autovacuum: processing database "test"
> > > LOG: autovacuum: processing database "test"
> > > LOG: autovacuum: processing database "test"
> > >
> > > This is certainly not desirable. I changed the message to DEBUG1 for
> > > 8.2 with the attached patch.
> >
> > IMHO this is less optimal, since the default installation will provide no way
> > for users to verify that autovacuum is running. Currently we can direct them
> > to look in thier log output, this way we would have to tell them to crank up
> > logging to DEBUG1 and then look, which will of course contain a whole lot of
> > other chatter at that level.
>
> Someone is working on it.
>
> > The best solution I have seen so far is the idea of a GUC to control
> > autovacuums chatter level. I hope we get that becuase the above will be a
> > regression imho.
>
> The purpose of the logs is not to show something _working_, but to
> report significant events. Frankly, even with the GUC, to see it is
> working you are still going to fill up the logs with activity.
>
> What do people want to know? --- that autovacuum is running, or how
> often. If it is the former, we can print something on server startup.
>
> We don't even really log checkpoints, so logging every autovacuum seems
> strange.

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

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

On Friday 28 April 2006 19:06, Bruce Momjian wrote:
> I am thinking, what do we want to show by default about autovacuum in
> the server logs. What if we output a line the first time autovacuum
> runs successfully on server start?
>

If Larry can do the work of getting details added into the stats views, I'm
comfortable just setting all of the logging to debug1 and leaving it at that.
I still could see the idea of having a guc for an autovacuum specific log
control; I could see an admin who first enables autovacuum might want to log
all its activity for some period of time; but the angle of "need to verify it
is turned on" goes away with the stats info.

--
Robert Treat
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL

Robert Treat <xzilla(at)users(dot)sourceforge(dot)net> writes:
> If Larry can do the work of getting details added into the stats views, I'm
> comfortable just setting all of the logging to debug1 and leaving it at that.
> I still could see the idea of having a guc for an autovacuum specific log
> control; I could see an admin who first enables autovacuum might want to log
> all its activity for some period of time; but the angle of "need to verify it
> is turned on" goes away with the stats info.

Yeah, there's a lot to be said for that point. I was about to object
that you might not have stats turned on, but if you're running autovac,
I guess you do...

So let's temporarily forget the idea of complicating autovac's logging
code, and instead see if the stats approach will solve the problem.

regards, tom lane