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 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.
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
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 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.
log4c is inspired by log4j, which seems to have become the defacto standard
tool for logging in the enterprise java world.
Andrew
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 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.
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.
Absent such a feature, one hack is to set the desired log_min_messages
value in conf file and send SIGHUP to just the process of interest and
revert the conf file back; but it's a hack.
Best regards,
--
Gurjeet Singh http://gurjeet.singh.im/
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?
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Tue, Jul 7, 2015 at 11:20 AM, Sawada Masahiko <sawada.mshk@gmail.com>
wrote:
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:
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 want the logging to be controlled per background process, so that user
can pick and choose how much detail they want from each process. In absence
of such a setting for a background process, the global log_min_messages
should control the logging.
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 would like this feature to be as simple as the current log_min_messages;
currently a superuser can do ALTER USER X SET log_min_messages = Y, and
control logging for specific users or databases or a combination of those.
In the same vein, setting autovacuum.log_min_messages in postgresql.conf,
or a corresponding ALTER SYSTEM should be enough to use a different setting
of log_min_messages inside autovacuum launcher and its worker processes.
I am using autovacuum process as an example, but the same is applicable to
other background processes as well. E.g. checkpointer.log_min_messages.
As for the implementation details, upon startup and after every reload, the
autovacuum launcher process will look for autovacuum.log_min_messages being
defined; if yes, it'd set the global variable log_min_messages in code to
that value, and if not defined in any of the conf files, the global
variable in code would be assigned whatever is assigned to the GUC param
log_min_messages. DefineCustomXXVariable() seems incapable of supporting
this behaviour, so we might have to invent a new one.
This will allow us to keep the current behaviour as default when
autovacuum.log_min_messages is not defined, and provide finer control over
autovacuum's logging by defining this variable, when needed.
Same goes for Checkpointer, BGWriter, WALWriter, and BGWorkers. BTW, the
facility we invent needn't be limited to log_min_messages, but it's just
what we need now.
Best regards,
--
Gurjeet Singh http://gurjeet.singh.im/