Re: vacuum output question

On Thu, 2008-11-13 at 17:30 -0700, Scott Marlowe wrote:

> > I had them run a vacuum analyze verbose on my database, and had these
> > lines come back which made me suspicious:
> >
> > INFO: index "ix_cpe_ispid" now contains 41626 row versions in 13727 pages
> > DETAIL: 5224 index row versions were removed.
> > 1543 index pages have been deleted, 1373 are currently reusable.
> > CPU 13.09s/3.51u sec elapsed 157.85 sec.
> >
> > INFO: index "ix_cpe_enable" now contains 41628 row versions in 29417 pages
> > DETAIL: 5224 index row versions were removed.
> > 3706 index pages have been deleted, 3291 are currently reusable.
> > CPU 31.27s/8.22u sec elapsed 687.60 sec.
> >
> > INFO: "cpe": found 5224 removable, 41626 nonremovable row versions in
> > 1303 pages
> > DETAIL: 0 dead row versions cannot be removed yet.
> > There were 22416 unused item pointers.
> > 0 pages are entirely empty.
> > CPU 44.46s/11.82u sec elapsed 852.85 sec.
>
> That's a fair bit of dead space, but 60k rows isn't really that many.
>
> > Why did those particular tables and indexes take _so_ long to vacuum?
> > Perhaps we have a disk level IO problem on this system?
>
> Assuming pagesize is 8k, then we're talking about scanning 1303*8192
> bytes or 10 Megabytes. My laptop can scan that in less than a second.
>
> So, either the hard drive is incredibly fragmented, or there's
> something wrong with that machine.

There was concurrent access to the table during VACUUMing, so the long
delay is explainable as long waits for cleanup lock, plus probably
thrashing the cache with bloated indexes. The CPU overhead per row seems
OK. We should instrument the wait time during a VACUUM and report that
also.

--
Simon Riggs www.2ndQuadrant.com
PostgreSQL Training, Services and Support