Why does autovacuum clean fewer rows than I expect?

From: Nick Cabatoff <nick(dot)cabatoff(at)gmail(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: Why does autovacuum clean fewer rows than I expect?
Date: 2014-07-03 21:07:37
Message-ID: CAHeYVxPA7WO1Q88vuK6ir5uXbjy1220c4zOmCeOZ1uPVMSLS=g@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi,

I'm having trouble making sense of the these two autovacuum log entries.
I'm running PostgreSQL 8.4.

[2014-05-22 04:56:43.486 EST] {537cf2c6.30f9} LOG: automatic vacuum of
table "postgres.globaldicom.requests": index scans: 1
pages: 0 removed, 163600 remain
tuples: 5916 removed, 8423598 remain
system usage: CPU 3.62s/9.84u sec elapsed 1060.49 sec

[2014-05-24 05:02:12.707 EST] {537f90c3.7144} LOG: automatic vacuum of
table "postgres.globaldicom.requests": index scans: 2
pages: 0 removed, 510725 remain
tuples: 1554 removed, 8583343 remain
system usage: CPU 9.19s/16.86u sec elapsed 2673.32 sec

I've verified that no vacuum (manual or auto) took place between them unless
they were basically no-ops, since log_autovacuum_min_duration=250.
Otherwise
we're using the stock autovacuum config settings, thus 3 workers, 1min
naptime,
autovacuum_vacuum_scale_factor=0.2, vacuum_cost_delay=0ms, etc.

First question: how do we get a 3x page usage increase with a <1% tuple
increase? The only thing I can think of is that a lot of very big values
were
stored. To my knowledge that didn't happen, but I can't rule it out
entirely.
Since I judge it quite unlikely I'm looking for alternate explanations of
what
might have happened.

Second question: What triggered the above autovacuums? From what I
understand
it must be one of imminent txid wraparound or exceeding
autovacuum_vacuum_scale_factor. If it was the latter, suggesting that 20%
of
the 8.5M tuples had changed, then why were only a few thousand tuples
removed?
I'm not sure how to eliminate the possibility that it was the former after
the
fact. However, I know that there was a lot of activity, going by the
auto-analyzes that took place (autovacuum_vacuum_analyze_factor=0.1):

[2014-05-20 11:08:59.632 EST] {537aab0a.b704} LOG: automatic analyze of
table "postgres.globaldicom.requests" system usage: CPU 0.36s/0.45u sec
elapsed 32.98 sec
[2014-05-23 21:12:49.164 EST] {537f2d12.459b} LOG: automatic analyze of
table "postgres.globaldicom.requests" system usage: CPU 0.08s/0.36u sec
elapsed 30.60 sec
[2014-05-24 00:56:00.927 EST] {537f6161.2b77} LOG: automatic analyze of
table "postgres.globaldicom.requests" system usage: CPU 0.16s/0.38u sec
elapsed 31.42 sec
[2014-05-24 06:33:16.972 EST] {537fb06d.e9e3} LOG: automatic analyze of
table "postgres.globaldicom.requests" system usage: CPU 0.15s/0.35u sec
elapsed 31.13 sec

This isn't an isolated incident, I see many autovacuum log entries where
only a
few tuples are removed from a very large table, and I can't figure out why
it
was being vacuumed if that's all there was to be removed.

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Quinlan Pfiffer 2014-07-03 21:10:08 Re: C++ Background Workers?
Previous Message Tom Lane 2014-07-03 21:00:50 Re: C++ Background Workers?