pgsql: Change log message about vacuuming database name from LOG to

momjian@postgresql.org (Bruce Momjian) writes:

Change log message about vacuuming database name from LOG to DEBUG1.
Prevents duplicate meaningless log messsages.

Could we have some discussion about this sort of thing, rather than
unilateral actions?

Those messages were at LOG level because otherwise it's difficult to be
sure from the log that autovac is running at all.

regards, tom lane

Tom Lane wrote:

momjian@postgresql.org (Bruce Momjian) writes:

Change log message about vacuuming database name from LOG to DEBUG1.
Prevents duplicate meaningless log messsages.

Could we have some discussion about this sort of thing, rather than
unilateral actions?

Those messages were at LOG level because otherwise it's difficult to be
sure from the log that autovac is running at all.

OK, so what do we want to do? Clearly outputing something everytime
pg_autovacuum touches a database isn't ideal. By default, the server
logs should show significant events, which this is not.

Do we want something output only the first time autovacuum runs?

--
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 think there are two things people typically want to know from the logs:
1) Is autovacuum running
2) Did autovacuum take action (issue a VACUUM or ANALYZE)

I don't think we need mention the name of each and every database we
touch, we can, but it should be at a lower level like DEBUG1 or something.

I don't know what logging level these thing should go at, but I for one
would like them to be fairly high easy to get to, perhaps NOTICE?

Matt

Bruce Momjian wrote:

Matthew T. O'Connor wrote:

I think there are two things people typically want to know from the logs:
1) Is autovacuum running
2) Did autovacuum take action (issue a VACUUM or ANALYZE)

I don't think we need mention the name of each and every database we
touch, we can, but it should be at a lower level like DEBUG1 or something.

OK, that part is done.

I don't know what logging level these thing should go at, but I for one
would like them to be fairly high easy to get to, perhaps NOTICE?

Interesting idea. I had forgotten that for server messages, LOG is at
the top, and ERROR, NOTICE, etc are below it. We could make them
NOTICE, but then all user NOTICE messages appear in the logs too. Yuck.

Do we want to LOG everytime autovacuum does something? Is that going to
fill up the logs worse than the per-database line?

The real issue is that we give users zero control over what autovacuum
logs, leading to the TODO item. I guess the question is until the TODO
item is done, what do we want to do?

How do people like the idea of having this in postgresql.conf:

autovacuum_set = 'set log_min_messages = ''error'''

and set autovacuum to output notice/info/error messages as desired by
the administrator? This shouldn't be too hard to do, and it is very
flexible.

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

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

Bruce Momjian wrote:

Matthew T. O'Connor wrote:

I think there are two things people typically want to know from the
logs: 1) Is autovacuum running 2) Did autovacuum take action (issue
a VACUUM or ANALYZE)

I don't think we need mention the name of each and every database we
touch, we can, but it should be at a lower level like DEBUG1 or
something.

OK, that part is done.

I don't know what logging level these thing should go at, but I for
one would like them to be fairly high easy to get to, perhaps NOTICE?

Interesting idea. I had forgotten that for server messages, LOG is at
the top, and ERROR, NOTICE, etc are below it. We could make them
NOTICE, but then all user NOTICE messages appear in the logs too.
Yuck.

Do we want to LOG everytime autovacuum does something? Is that going
to fill up the logs worse than the per-database line?

My general take is I (as an admin), want to know that:
a) autovacuum is doing it's periodic checks
b) when it actually vacuums a (database|table) we know what time it did
it.

The real issue is that we give users zero control over what autovacuum
logs, leading to the TODO item. I guess the question is until the
TODO item is done, what do we want to do?

How do people like the idea of having this in postgresql.conf:

autovacuum_set = 'set log_min_messages = ''error'''

and set autovacuum to output notice/info/error messages as desired by
the administrator? This shouldn't be too hard to do, and it is very
flexible.

We definitely need to do "something" wrt autovacuum messages,
but this doesn't say what gets logged at what level for autovacuum.

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

LER

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

I would argue that what people typically want is

(0) nothing

(1) per-database log messages

or

(2) per-table log messages (including per-database)

The first problem is that (2) is only available at DEBUG2 or below,
which is not good because that also clutters the log with a whole lot of
implementer-level debugging info.

The second problem is that we don't really want to use the global
log_min_messages setting to determine this, because that constrains
your decision about how much chatter you want from ordinary backends.

I suggest that maybe the cleanest solution is to not use log level at
all for this, but to invent a separate "autovacuum_verbosity" setting
that controls how many messages autovac tries to log, using the above
scale. Anything it does try to log can just come out at LOG message
setting.

regards, tom lane

On 4/27/06, Tom Lane <tgl@sss.pgh.pa.us> wrote:

I suggest that maybe the cleanest solution is to not use log level at
all for this, but to invent a separate "autovacuum_verbosity" setting
that controls how many messages autovac tries to log, using the above
scale. Anything it does try to log can just come out at LOG message
setting.

/me agrees this is by all accounts, the best and cleanest option.

--
Jonah H. Harris, Database Internals Architect
EnterpriseDB Corporation
732.331.1324

Tom Lane wrote:

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

I would argue that what people typically want is

(0) nothing

(1) per-database log messages

or

(2) per-table log messages (including per-database)

The first problem is that (2) is only available at DEBUG2 or below,
which is not good because that also clutters the log with a whole lot
of implementer-level debugging info.

The second problem is that we don't really want to use the global
log_min_messages setting to determine this, because that constrains
your decision about how much chatter you want from ordinary backends.

I suggest that maybe the cleanest solution is to not use log level at
all for this, but to invent a separate "autovacuum_verbosity" setting
that controls how many messages autovac tries to log, using the above
scale. Anything it does try to log can just come out at LOG message
setting.

This sounds like a winner to me. Anyone else want to grab it? I'm
in the position to try and do this, but don't want to step on anyone
else's toes.

LER

regards, tom lane

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

tgl@sss.pgh.pa.us (Tom Lane) writes:

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

I would argue that what people typically want is

(0) nothing

(1) per-database log messages

or

(2) per-table log messages (including per-database)

The first problem is that (2) is only available at DEBUG2 or below,
which is not good because that also clutters the log with a whole
lot of implementer-level debugging info.

The second problem is that we don't really want to use the global
log_min_messages setting to determine this, because that constrains
your decision about how much chatter you want from ordinary
backends.

I suggest that maybe the cleanest solution is to not use log level
at all for this, but to invent a separate "autovacuum_verbosity"
setting that controls how many messages autovac tries to log, using
the above scale. Anything it does try to log can just come out at
LOG message setting.

At "level 2," it seems to me that it would be quite useful to have
some way of getting at the verbose output of VACUUM.

Consider when I vacuum a table, thus:

/* cbbrowne@[local]/dba2 performance=*/ vacuum verbose analyze days;
INFO: vacuuming "public.days"
INFO: "days": found 0 removable, 1893 nonremovable row versions in 9 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.03 sec.
INFO: analyzing "public.days"
INFO: "days": 9 pages, 1893 rows sampled, 1893 estimated total rows
VACUUM

The only thing that PostgreSQL will log generally about this is, if
the query runs for a while, that I requested "vacuum verbose analyze
days;", and that this took 4284ms to run.

It would be really nice if we could have some way of logging the
details, namely of numbers of row versions removed/nonremovable, and
of pages affected.

If we could regularly log that sort of information, that could be very
useful in figuring out some "more nearly optimal" schedule for
vacuuming.

One of our people wrote a Perl script that will take verbose VACUUM
output and essentially parses it so as to be able to generate a bunch
of SQL queries to try to collect how much time was spent, and what
sorts of changes got accomplished.

At present, getting anything out of that mandates that every VACUUM
request have stdout tied to this Perl script, which I'm not overly
keen on, for any number of reasons, notably:

- Any vacuums run separately aren't monitored at all

- Parsing not-forcibly-stable-across-versions file formats with Perl
is a fragile thing

- Ideally, this would be nice to get into the PG "engine," somewhere,
whether as part of standard logging, or as part of how pg_autovacuum
works...

Having some ability to collect statistics about "we recovered 42 pages
from table foo at 12:45" would seem useful both from an immediate
temporal perspective where it could suggest whether specific tables
were being vacuumed too (seldom|often), and from a more
global/analytic perspective of perhaps suggesting better kinds of
vacuuming policies. (In much the same way that I'd like to have some
way of moving towards an analytically better value for
default_statistics_target than 10...)

If people are interested, I could provide a copy of the "analyze
VACUUM stats" script...
--
(reverse (concatenate 'string "gro.mca" "@" "enworbbc"))
http://www.ntlug.org/~cbbrowne/sgml.html
"I would rather spend 10 hours reading someone else's source code than
10 minutes listening to Musak waiting for technical support which
isn't." -- Dr. Greg Wettstein, Roger Maris Cancer Center

Uh, while you are at it, the background writer and checkpoint operations
need similar treatment. :-)

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

Larry Rosenman wrote:

Tom Lane wrote:

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

I would argue that what people typically want is

(0) nothing

(1) per-database log messages

or

(2) per-table log messages (including per-database)

The first problem is that (2) is only available at DEBUG2 or below,
which is not good because that also clutters the log with a whole lot
of implementer-level debugging info.

The second problem is that we don't really want to use the global
log_min_messages setting to determine this, because that constrains
your decision about how much chatter you want from ordinary backends.

I suggest that maybe the cleanest solution is to not use log level at
all for this, but to invent a separate "autovacuum_verbosity" setting
that controls how many messages autovac tries to log, using the above
scale. Anything it does try to log can just come out at LOG message
setting.

This sounds like a winner to me. Anyone else want to grab it? I'm
in the position to try and do this, but don't want to step on anyone
else's toes.

LER

regards, tom lane

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

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

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

Bruce Momjian wrote:

Uh, while you are at it, the background writer and checkpoint
operations need similar treatment. :-)

Sure.....

I'm willing to look at and work it out, if no one else is currently
working on it.

LER

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

This sounds like a winner to me. Anyone else want to grab it? I'm
in the position to try and do this, but don't want to step on anyone
else's toes.

LER

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

Chris Browne <cbbrowne@acm.org> writes:

At "level 2," it seems to me that it would be quite useful to have
some way of getting at the verbose output of VACUUM.

I think you can do that now, if you set min_log_level to INFO. However,
it might be cleaner if we allowed a "level 3" that made all of autovac's
vacuums be VERBOSE.

regards, tom lane

Tom Lane wrote:

Chris Browne <cbbrowne@acm.org> writes:

At "level 2," it seems to me that it would be quite useful to have
some way of getting at the verbose output of VACUUM.

I think you can do that now, if you set min_log_level to INFO.
However, it might be cleaner if we allowed a "level 3" that made all
of autovac's vacuums be VERBOSE.

I was thinking along those exact lines. (A 3rd level).

LER

--
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 512-248-2683 E-Mail: ler@lerctr.org
US Mail: 430 Valona Loop, Round Rock, TX 78681-3893

Larry Rosenman wrote:

Tom Lane wrote:

Chris Browne <cbbrowne@acm.org> writes:

At "level 2," it seems to me that it would be quite useful to have
some way of getting at the verbose output of VACUUM.

I think you can do that now, if you set min_log_level to INFO.
However, it might be cleaner if we allowed a "level 3" that made all
of autovac's vacuums be VERBOSE.

I was thinking along those exact lines. (A 3rd level).

Also it'd be nice to have it a (4th?) level which would show the results
of the equations being applied.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Alvaro Herrera <alvherre@commandprompt.com> writes:

Also it'd be nice to have it a (4th?) level which would show the results
of the equations being applied.

That I think would fall more naturally into the category of debug
support --- I'm happy if we just emit that at DEBUG1 and let people
select it with log_min_messages.

regards, tom lane

Tom Lane wrote:

Alvaro Herrera <alvherre@commandprompt.com> writes:

Also it'd be nice to have it a (4th?) level which would show the
results of the equations being applied.

That I think would fall more naturally into the category of debug
support --- I'm happy if we just emit that at DEBUG1 and let people
select it with log_min_messages.

regards, tom lane

I was going to make that same comment, as this seems to be more
implementation
detail, which should be at DEBUGn.

LER

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

On Thu, 2006-04-27 at 14:53 -0400, Tom Lane wrote:

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

autovacuum_verbosity

Should we call it autovacuum_messages?

In current usage...

_verbosity controls how much information each message gives
_messages controls what types of messages are logged

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com/

Simon Riggs wrote:

On Thu, 2006-04-27 at 14:53 -0400, Tom Lane wrote:

"Larry Rosenman" <lrosenman@pervasive.com> writes:

I'd like to see a more concrete definition of what we
want Autovacuum to output and at what levels.

autovacuum_verbosity

Should we call it autovacuum_messages?

In current usage...

_verbosity controls how much information each message gives
_messages controls what types of messages are logged

That probably works, but I'm not sure about the one to add the VERBOSE
to the
VACUUM commands autovacuum.c emits.

--
Larry Rosenman
Database Support Engineer

PERVASIVE SOFTWARE. INC.
12365B RIATA TRACE PKWY
3015
AUSTIN TX 78727-6531

Tel: 512.231.6173
Fax: 512.231.6597
Email: Larry.Rosenman@pervasive.com
Web: www.pervasive.com

Those messages were at LOG level because otherwise it's difficult to be
sure from the log that autovac is running at all.

OK, so what do we want to do? Clearly outputing something everytime
pg_autovacuum touches a database isn't ideal. By default, the server
logs should show significant events, which this is not.

Do we want something output only the first time autovacuum runs?

I've considered several times proposing that I want to be able to turn
off or do something about autovacuum log messages. I just always
thought it would be rejected.

I have it set up so that I get the last few hundred lines of my postgres
logs mailed to me each day. However, most of the time I just get a few
hundred autovacuum messages. So, I had to much around with grepping out
the autovacuum lines, etc.

I personally don't see the point of there being soooo many of those
autovacuum log messages...

Chris