Re: obsessive-compulsive vacuum behavior

On Sun, Mar 7, 2010 at 11:58 PM, Ben Chobot <bench(at)silentmedia(dot)com> wrote:
> I've got an 8.4.2 database where it appears that vacuum keeps redoing the same table and indexes, never thinking it's finished:
>
> auditor=# VACUUM analyze VERBOSE repair_queue ;
> INFO:  vacuuming "public.repair_queue"
> INFO:  scanned index "repair_queue_pkey" to remove 2795932 row versions
> DETAIL:  CPU 14.98s/15.29u sec elapsed 312.50 sec.
> INFO:  scanned index "repair_queue_auditor" to remove 2795932 row versions
> DETAIL:  CPU 0.74s/0.50u sec elapsed 10.49 sec.
> INFO:  scanned index "repair_queue_sort" to remove 2795932 row versions
> DETAIL:  CPU 2.99s/1.58u sec elapsed 45.14 sec.
> INFO:  scanned index "repair_queue_sort3" to remove 2795932 row versions
> DETAIL:  CPU 0.89s/0.48u sec elapsed 10.99 sec.
> INFO:  "repair_queue": removed 2795932 row versions in 43199 pages
> DETAIL:  CPU 1.04s/0.39u sec elapsed 17.93 sec.
> INFO:  scanned index "repair_queue_pkey" to remove 2795938 row versions
> DETAIL:  CPU 14.71s/15.06u sec elapsed 362.37 sec.
> INFO:  scanned index "repair_queue_auditor" to remove 2795938 row versions
> DETAIL:  CPU 0.62s/0.45u sec elapsed 14.36 sec.
> INFO:  scanned index "repair_queue_sort" to remove 2795938 row versions
> DETAIL:  CPU 2.97s/1.65u sec elapsed 56.94 sec.
> INFO:  scanned index "repair_queue_sort3" to remove 2795938 row versions
> DETAIL:  CPU 0.82s/0.44u sec elapsed 10.54 sec.
> INFO:  "repair_queue": removed 2795938 row versions in 41055 pages
> DETAIL:  CPU 0.75s/0.34u sec elapsed 7.59 sec.
> INFO:  scanned index "repair_queue_pkey" to remove 2795959 row versions
> DETAIL:  CPU 14.20s/14.56u sec elapsed 539.17 sec.
> INFO:  scanned index "repair_queue_auditor" to remove 2795959 row versions
> DETAIL:  CPU 0.75s/0.48u sec elapsed 13.76 sec.
> INFO:  scanned index "repair_queue_sort" to remove 2795959 row versions
> DETAIL:  CPU 3.07s/1.65u sec elapsed 44.29 sec.
> INFO:  scanned index "repair_queue_sort3" to remove row versions
> DETAIL:  CPU 0.78s/0.44u sec elapsed 12.52 sec.
> INFO:  "repair_queue": removed 2795959 row versions in 41004 pages
> DETAIL:  CPU 0.88s/0.42u sec elapsed 12.49 sec.
>
>
> ...and so on. It's been running for an hour or so now, when it appears it shouldn't take 10 minutes. This seems pretty weird to me.... has anybody else seen this behavior? I'm not even sure what details I could report which would help figure out what's going on.

Those are all different relations, and it's reclaiming a good number
of rows and pages. 41004 pages is ~320 Megs. Even if the rows are
small it's gonna be 100 Megs or so per index reclaimed. Seems like
vacuum is doing its job. Is it running often enough to prevent
bloating?