Thread: More logging for autovacuum

I'm having trouble following what's going on with autovacuum and I'm finding
the existing logging insufficient. In particular that it's only logging vacuum
runs *after* the vacuum finishes makes it hard to see what vacuums are running
at any given time. Also, I want to see what is making autovacuum decide to
forgo vacuuming a table and the log with that information is at DEBUG2.

So I would like to suggest adding two options:

log_autovacuum_jobs - output every time a vacuum or analyze *starts*

log_autovacuum_level - set the log level for the autovacuum process

I would also suggest raising the level of the DEBUG2 message indicating why
tables were chosen or not. At least to DEBUG1 if not to INFO.

Am I missing anything? Are there ways to get this info already that I'm
missing? I imagine it would be pretty simple to add these and I'll be happy to
do it and send the patch to -patches assuming others (Alvaro? :) agree.

--  Gregory Stark EnterpriseDB          http://www.enterprisedb.com

Gregory Stark <stark@enterprisedb.com> writes:
> I would also suggest raising the level of the DEBUG2 message indicating why
> tables were chosen or not. At least to DEBUG1 if not to INFO.

It's not acceptable for autovacuum to be cluttering the log by default.
        regards, tom lane

Gregory Stark wrote:
> I'm having trouble following what's going on with autovacuum and I'm finding
> the existing logging insufficient. In particular that it's only logging vacuum
> runs *after* the vacuum finishes makes it hard to see what vacuums are running
> at any given time. Also, I want to see what is making autovacuum decide to
> forgo vacuuming a table and the log with that information is at DEBUG2.
> 
> So I would like to suggest adding two options:
> 
> log_autovacuum_jobs - output every time a vacuum or analyze *starts*
> 
> log_autovacuum_level - set the log level for the autovacuum process
> 
> I would also suggest raising the level of the DEBUG2 message indicating why
> tables were chosen or not. At least to DEBUG1 if not to INFO.
> 
> Am I missing anything? Are there ways to get this info already that I'm
> missing? I imagine it would be pretty simple to add these and I'll be happy to
> do it and send the patch to -patches assuming others (Alvaro? :) agree.


I think this sounds good.  There was talk a while ago about need a 
special log level setting just for autovacuum, but nobody did the leg 
work.

Le mardi 07 août 2007, Tom Lane a écrit :
> Gregory Stark <stark@enterprisedb.com> writes:
> > log_autovacuum_jobs - output every time a vacuum or analyze *starts*
[...]
> > I would also suggest raising the level of the DEBUG2 message indicating
> > why tables were chosen or not. At least to DEBUG1 if not to INFO.
>
> It's not acceptable for autovacuum to be cluttering the log by default.

If I understand correctly what is proposed, the log_autovacuum_jobs option
would allow the user to choose whether or not he wants its log cluttered by
autovacuum. I know I'd choose to clutter them, and would prefer not having to
choose a DEBUG loglevel to have autovacuum logs...

Regards,
--
dim

"Tom Lane" <tgl@sss.pgh.pa.us> writes:

> Gregory Stark <stark@enterprisedb.com> writes:
>> I would also suggest raising the level of the DEBUG2 message indicating why
>> tables were chosen or not. At least to DEBUG1 if not to INFO.
>
> It's not acceptable for autovacuum to be cluttering the log by default.

Well log_min_messages is NOTICE by default so neither INFO nor DEBUG1 would
actually clutter the logs by default, but it sounds like you would prefer at
most DEBUG1?

--  Gregory Stark EnterpriseDB          http://www.enterprisedb.com

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Dimitri Fontaine wrote:
> Le mardi 07 août 2007, Tom Lane a écrit :
>> Gregory Stark <stark@enterprisedb.com> writes:
>>> log_autovacuum_jobs - output every time a vacuum or analyze *starts*
> [...]
>>> I would also suggest raising the level of the DEBUG2 message indicating
>>> why tables were chosen or not. At least to DEBUG1 if not to INFO.
>> It's not acceptable for autovacuum to be cluttering the log by default.
> 
> If I understand correctly what is proposed, the log_autovacuum_jobs option 
> would allow the user to choose whether or not he wants its log cluttered by 
> autovacuum. I know I'd choose to clutter them, and would prefer not having to 
> choose a DEBUG loglevel to have autovacuum logs...

With 8.3 having autovacuum on by default, we really should be logging at
a mininum:

autovacuum start
autovacuum working (what am I working on but not what I am doing,
meaning we don't need tuple information etc..)
autovacuum stop

Yes, by default or at least at no level higher than INFO.

Sincerely,

Joshua D. Drake



> 
> Regards,


- --
     === The PostgreSQL Company: Command Prompt, Inc. ===
Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240
Providing the most comprehensive  PostgreSQL solutions since 1997            http://www.commandprompt.com/

Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate
PostgreSQL Replication: http://www.commandprompt.com/products/

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGuJJIATb/zqfZUUQRApl7AJoCq85I0drgIUg1BEn/2ngrSKCQTwCgoIik
ZmLO2N/2nQLNdNJeKUwhQEo=
=nLKN
-----END PGP SIGNATURE-----

"Joshua D. Drake" <jd@commandprompt.com> writes:
> With 8.3 having autovacuum on by default, we really should be logging at
> a mininum:

> autovacuum start
> autovacuum working (what am I working on but not what I am doing,
> meaning we don't need tuple information etc..)
> autovacuum stop

> Yes, by default or at least at no level higher than INFO.

No, NOT by default.  Our users have made it perfectly clear that they
don't want the logs cluttered with high-volume information about
non-error normal workings of the system.  Every time we have caused
the system to emit such data by default, the log level of the messages
in question has gotten dialed down in a later release.

I don't object to what Greg suggests as an option.  If we try to make
it the default behavior, we will find ourselves changing that.

As far as the debug/info/etc discussion goes: if there is a GUC variable
controlling it, just make the elevel be LOG.
        regards, tom lane

Tom Lane wrote:
> > Yes, by default or at least at no level higher than INFO.
>
> No, NOT by default.  Our users have made it perfectly clear that they
> don't want the logs cluttered with high-volume information about
> non-error normal workings of the system.  Every time we have caused
> the system to emit such data by default, the log level of the
> messages in question has gotten dialed down in a later release.

But INFO is not shown by default.

In fact, just about the only useful thing that emits INFO messages is 
VACUUM VERBOSE, so there is a fair precedent for equating the INFO 
level with lots of chatter about VACUUM.

I like to set log_min_messages to INFO (and run vacuum verbosely) while 
a system is stabilizing, so adding autovacuum information there would 
come in handy.

-- 
Peter Eisentraut
http://developer.postgresql.org/~petere/

Peter Eisentraut <peter_e@gmx.net> writes:
> But INFO is not shown by default.

INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient
behavior before we redesigned the elog levels.  It's intended for
controlling messages that should go to a client because the client
asked for them, and usually should NOT go to the log.  I think it's
100% inappropriate to use it for messages from a background process
that has no client.
        regards, tom lane

On Tue, Aug 07, 2007 at 11:59:03AM -0700, Andrew Hammond wrote:
> On 8/7/07, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> >
> > Peter Eisentraut <peter_e@gmx.net> writes:
> > > But INFO is not shown by default.
> >
> > INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient
> > behavior before we redesigned the elog levels.  It's intended for
> > controlling messages that should go to a client because the client
> > asked for them, and usually should NOT go to the log.  I think it's
> > 100% inappropriate to use it for messages from a background process
> > that has no client.
> >
>
> Traditional log-level semantics aren't very rich. I think that's the real
> source of this problem: "How do I get the info I need to tune auto-vacuum
> without swamping my system with log IO". While the following isn't
> production ready, it seems to have some really good ideas.

Is logging really the answer for that? ISTM it'd be better to provide
statistics info so that you could monitor autovacuum activity with
things like cricket, SNMP, etc.
--
Decibel!, aka Jim Nasby                        decibel@decibel.org
EnterpriseDB      http://enterprisedb.com      512.569.9461 (cell)

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Decibel! wrote:
> On Tue, Aug 07, 2007 at 11:59:03AM -0700, Andrew Hammond wrote:
>> On 8/7/07, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>>> Peter Eisentraut <peter_e@gmx.net> writes:
>>>> But INFO is not shown by default.
>>> INFO is mostly a hack to try to emulate VACUUM VERBOSE's ancient
>>> behavior before we redesigned the elog levels.  It's intended for
>>> controlling messages that should go to a client because the client
>>> asked for them, and usually should NOT go to the log.  I think it's
>>> 100% inappropriate to use it for messages from a background process
>>> that has no client.
>>>
>> Traditional log-level semantics aren't very rich. I think that's the real
>> source of this problem: "How do I get the info I need to tune auto-vacuum
>> without swamping my system with log IO". While the following isn't
>> production ready, it seems to have some really good ideas.
> 
> Is logging really the answer for that? ISTM it'd be better to provide
> statistics info so that you could monitor autovacuum activity with
> things like cricket, SNMP, etc.

Well that would certainly be useful too.

Joshua D. Drake



- --
     === The PostgreSQL Company: Command Prompt, Inc. ===
Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240
Providing the most comprehensive  PostgreSQL solutions since 1997            http://www.commandprompt.com/

Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate
PostgreSQL Replication: http://www.commandprompt.com/products/

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGuOZBATb/zqfZUUQRAmy6AKCohv/RtFmPCA+zmmpkwR1qCX3XugCgg/rE
lq3wxodgiWNe0d1wmw1ragc=
=X6W3
-----END PGP SIGNATURE-----

On Tue, 7 Aug 2007, Decibel! wrote:

> Is logging really the answer for that? ISTM it'd be better to provide
> statistics info so that you could monitor autovacuum activity with
> things like cricket, SNMP, etc.

There are two sides to this.  One is that it's difficult to right now to 
tell when your performance is being whacked because autovacuum is doing 
something.  The original version of the checkpoint + other slowdowns 
logging patch I submitted included a line of extra detail there so I could 
watch the entry/exit to every autovaccum section if the log level was 
cranked up to DEBUG2, motivated by the same reasons Greg Stark mentioned.

When you get into a situation where things are inexplicably slow, it's 
nice to do a tail on the logs and be able to figure out "oh, it's busy 
vacuuming X right now, no wonder".  Just logging when you're going through 
that is good enough to let you line up the timestamps with other system 
activity measurements, and while difficult you can tune based just on 
that.  And having that information easily available in the logs lets 
almost any level of user watch what's going on.

Actually tuning that behavior out of the system altogether is easier done 
by collecting statistics, in a similar fashion to how pg_stat_bgwriter 
lets you track checkpoints now, but that being helpful presumes a level of 
monitoring sophistication that typical new installations (who need this 
kind of help the most) don't have.  Also, given the way that the stats are 
often updated after the work was done, that implementation may not solve 
the "why am I slow right now?" side of the problem effectively.

I think both types of instrumentation are ultimately needed, but if you 
were only picking one I think the log entries would be the better one to 
start with.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD

Gregory Stark wrote:
> 
> I'm having trouble following what's going on with autovacuum and I'm finding
> the existing logging insufficient. In particular that it's only logging vacuum
> runs *after* the vacuum finishes makes it hard to see what vacuums are running
> at any given time. Also, I want to see what is making autovacuum decide to
> forgo vacuuming a table and the log with that information is at DEBUG2.

So did this idea go anywhere?

-- 
Alvaro Herrera                          Developer, http://www.PostgreSQL.org/
Officer Krupke, what are we to do?
Gee, officer Krupke, Krup you! (West Side Story, "Gee, Officer Krupke")

On Sat, Jul 4, 2015 at 2:30 PM, Amit Kapila <amit.kapila16@gmail.com> wrote:
> On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh <gurjeet@singh.im> wrote:
>>
>> On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera
>> <alvherre@commandprompt.com> wrote:
>>>
>>> Gregory Stark wrote:
>>> >
>>> > I'm having trouble following what's going on with autovacuum and I'm
>>> > finding
>>> > the existing logging insufficient. In particular that it's only logging
>>> > vacuum
>>> > runs *after* the vacuum finishes makes it hard to see what vacuums are
>>> > running
>>> > at any given time. Also, I want to see what is making autovacuum decide
>>> > to
>>> > forgo vacuuming a table and the log with that information is at DEBUG2.
>>>
>>> So did this idea go anywhere?
>>
>>
>> Assuming the thread stopped here, I'd like to rekindle the proposal.
>>
>> log_min_messages acts as a single gate for everything headed for the
>> server logs; controls for per-background process logging do not exist. If
>> one wants to see DEBUG/INFO messages for just the Autovacuum (or
>> checkpointer, bgwriter, etc.), they have to set log_min_messages to that
>> level, but the result would be a lot of clutter from other processes to
>> grovel through, to see the messages of interest.
>>
>
> I think that will be quite helpful.  During the patch development of
> parallel sequential scan, it was quite helpful to see the LOG messages
> of bgworkers, however one of the recent commits (91118f1a) have
> changed those to DEBUG1, now if I have to enable all DEBUG1
> messages, then what I need will be difficult to find in all the log
> messages.
> Having control of separate logging for background tasks will serve such
> a purpose.
>
>> The facilities don't yet exist, but it'd be nice if such parameters when
>> unset (ie NULL) pick up the value of log_min_messages. So by default, the
>> users will get the same behaviour as today, but can choose to tweak per
>> background-process logging when needed.
>>
>
> Will this proposal allow user to see all the messages by all the background
> workers or will it be per background task.  Example in some cases user
> might want to see the messages by all bgworkers and in some cases one
> might want to see just messages by AutoVacuum and it's workers.
>
> I think here designing User Interface is an important work if others also
> agree
> that such an option is useful, could you please elaborate your proposal?

+1

I sometime want to set log_min_messages per process, especially when
less than DEBUG level log is needed.
It's not easy to set log level to particular process from immediately
after beginning of launch today.

Regards,

--
Sawada Masahiko

On Sat, Jul 4, 2015 at 2:30 PM, Amit Kapila <amit.kapila16@gmail.com> wrote:
> On Thu, Jul 2, 2015 at 4:41 AM, Gurjeet Singh <gurjeet@singh.im> wrote:
>>
>> On Fri, Aug 17, 2007 at 3:14 PM, Alvaro Herrera
>> <alvherre@commandprompt.com> wrote:
>>>
>>> Gregory Stark wrote:
>>> >
>>> > I'm having trouble following what's going on with autovacuum and I'm
>>> > finding
>>> > the existing logging insufficient. In particular that it's only logging
>>> > vacuum
>>> > runs *after* the vacuum finishes makes it hard to see what vacuums are
>>> > running
>>> > at any given time. Also, I want to see what is making autovacuum decide
>>> > to
>>> > forgo vacuuming a table and the log with that information is at DEBUG2.
>>>
>>> So did this idea go anywhere?
>>
>>
>> Assuming the thread stopped here, I'd like to rekindle the proposal.
>>
>> log_min_messages acts as a single gate for everything headed for the
>> server logs; controls for per-background process logging do not exist. If
>> one wants to see DEBUG/INFO messages for just the Autovacuum (or
>> checkpointer, bgwriter, etc.), they have to set log_min_messages to that
>> level, but the result would be a lot of clutter from other processes to
>> grovel through, to see the messages of interest.
>>
>
> I think that will be quite helpful.  During the patch development of
> parallel sequential scan, it was quite helpful to see the LOG messages
> of bgworkers, however one of the recent commits (91118f1a) have
> changed those to DEBUG1, now if I have to enable all DEBUG1
> messages, then what I need will be difficult to find in all the log
> messages.
> Having control of separate logging for background tasks will serve such
> a purpose.
>

+1

I sometime want to set log_min_messages per process, especially when
less than DEBUG level log is needed.
It's not easy to set log level to particular process from immediately
after beginning of launch today.

Regards,

--
Sawada Masahiko