log_autovacuum

On Thu, 2007-03-08 at 16:05 +0000, Simon Riggs wrote:

LOG: autovac "public.w" scans:1 pages:197(-0) tuples:2338(-7199) CPU
0.00s/0.00u sec elapsed 0.39 sec

Seems like a pretty cryptic log format to me.

-Neil

Simon Riggs wrote:

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

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

On March 8, 2007 09:53 am, Alvaro Herrera wrote:

Simon Riggs wrote:

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

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.

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/

Darcy Buskermolen wrote:

On March 8, 2007 09:53 am, Alvaro Herrera wrote:

Keep in mind that it's going to be translated, so it's not useful for
machine parsing anyway.

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.

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:

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"

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.

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

Hi,

On 3/9/07, Simon Riggs <simon@2ndquadrant.com> wrote:

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:

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"

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.

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

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

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.

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

Simon Riggs wrote:

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:

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"

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.

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

[ Attachment, skipping... ]

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com

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

Simon Riggs wrote:

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:

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"

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.

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.

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

On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote:

Simon Riggs wrote:

On Thu, 2007-03-08 at 14:53 -0300, Alvaro Herrera wrote:

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"

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.

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.

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
tuples: 1300683 removed, 1096236 remain

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

Alvaro Herrera <alvherre@commandprompt.com> writes:

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 be a bit more consistent about whether numbers precede or follow
their descriptions. "x removed, y remain" might work.

regards, tom lane

Tom Lane wrote:

Alvaro Herrera <alvherre@commandprompt.com> writes:

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 be a bit more consistent about whether numbers precede or follow
their descriptions. "x removed, y remain" might work.

Fixed.

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

Simon Riggs wrote:

On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote:

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.

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.

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?

Presumably you mean to have both removeds in the same order?

pages: 0 removed, 11226 remain
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

Alvaro Herrera <alvherre@commandprompt.com> writes:

Simon Riggs wrote:

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.

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.

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

On Tue, 2007-04-17 at 14:45 -0400, Alvaro Herrera wrote:

Simon Riggs wrote:

On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote:

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.

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.

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.

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

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?

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

Time is a more natural unit than tuples removed.

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

In response to Alvaro Herrera <alvherre@commandprompt.com>:

Simon Riggs wrote:

On Tue, 2007-04-17 at 14:06 -0400, Alvaro Herrera wrote:

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.

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.

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?

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/

wmoran@collaborativefusion.com
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.
****************************************************************

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

regards, tom lane

Tom Lane wrote:

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

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

Maybe it should be in autovacuum.c.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On Tue, 2007-04-17 at 16:41 -0400, Alvaro Herrera wrote:

Tom Lane wrote:

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

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

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.

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

Alvaro Herrera wrote:

Tom Lane wrote:

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

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

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?

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.