Postgresql 8.0 beta 1 - strange cpu usage statistics and slow vacuuming

[Shelby Cain]

I'm putting 8.0 through its paces and here are a few
things I've noticed on the native win32 port running
on my workstation (2.0g p4 w/256 megs of ram).

Here is the output of "vacuum verbose item":

=============== =====
INFO: vacuuming "public.ite m"
INFO: "item": removed 246381 row versions in 24044
pages
DETAIL: CPU -1.-1612s/-1.99u sec elapsed 1434.79 sec.
INFO: "item": found 246381 removable, 492935
nonremovable row versions in 50413 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 100991 unused item pointers.
0 pages are entirely empty.
CPU 1081264882.-821s/0.02u sec elapsed 1682.87 sec.

Query returned successfully with no result in 1683460
ms.
=============== =====

As you can see the cpu statistics are obviously bogus
although the elasped time is correct.

My other concern is the length of time that vacuum
runs when cost based vacuuming is disabled.

Under 8.0, if I run an update statement (update item
where set cost = cost + 0 where country = 'US' [causes
an update w/o really changing data]) that updates half
the rows in the table (~250k out of 500k - average
tuple width is about 500 bytes) and then execute a
regular vacuum it takes approximately 1400 seconds to
complete. A vacuum full performed immediately after
takes on the order of 2000 seconds to complete.

During the update, I see anywhere from 5 to 10 meg/s
of disk transfer, an average disk queue length of 1-2
and a relatively large number of split I/O operations
per second (as reported via performance monitor).
However, during vacuum and vacuum full (once they
begin in earnest) I see less than 1 meg/s of disk
transfer, an average disk queue length of less than 1
and a virtually no split I/O operations per second.

With the same table data loaded under 7.4.x on cygwin
it takes approximately 100 seconds to complete the
vacuum after the same update. A vacuum full run
immediately afterwards on the table takes around 250
seconds to complete.

During the update, vacuum and vacuum full I see
anywhere from 5 to 10 meg/s of disk transfer, an
average disk queue length of 1-2 and a relatively
large number of split I/O operations per second (as
reported via performance monitor).

In both cases, cpu usage is nil and the 7.4.x and 8.0
..conf files are virtually indentical. Can anyone
offer an explanation as to why I'm seeing such a huge
performance difference in vacuum between 7.4.x and
8.0?

Regards,

Shelby Cain


_______________ _______________ ____
Do you Yahoo!?
New and Improved Yahoo! Mail - Send 10MB messages!
http://promotions.yahoo.com/new_mail

---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to ma*******@postg resql.org

[Tom Lane]

Shelby Cain <al******@yahoo .com> writes:

I'm putting 8.0 through its paces and here are a few
things I've noticed on the native win32 port running
on my workstation (2.0g p4 w/256 megs of ram). Here is the output of "vacuum verbose item": DETAIL: CPU -1.-1612s/-1.99u sec elapsed 1434.79 sec.
...
CPU 1081264882.-821s/0.02u sec elapsed 1682.87 sec.
Hmm ... something broken about getrusage() on Windows?
CC'd to pgsql-hackers-win32 for comment.
My other concern is the length of time that vacuum
runs when cost based vacuuming is disabled.

Are you sure you had cost-based vac disabled? I tried to reproduce
your experiment here. I saw some degradation in vacuuming speed
but not nearly as large as you're reporting (85 vs 73 seconds),
and as far as I could tell it was still maxing out my disk.
But the behavior you're describing is exactly what I'd expect if
cost-based vac was on.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: the planner will ignore your desire to choose an index scan if your
joining column's datatypes do not match

[Gaetano Mendola]

Shelby Cain wrote:

I'm putting 8.0 through its paces and here are a few
things I've noticed on the native win32 port running
on my workstation (2.0g p4 w/256 megs of ram).

Here is the output of "vacuum verbose item":

=============== =====
INFO: vacuuming "public.ite m"
INFO: "item": removed 246381 row versions in 24044
pages
DETAIL: CPU -1.-1612s/-1.99u sec elapsed 1434.79 sec.
INFO: "item": found 246381 removable, 492935
nonremovable row versions in 50413 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 100991 unused item pointers.
0 pages are entirely empty.
CPU 1081264882.-821s/0.02u sec elapsed 1682.87 sec.

Query returned successfully with no result in 1683460
ms.
=============== =====

As you can see the cpu statistics are obviously bogus
although the elasped time is correct.

My other concern is the length of time that vacuum
runs when cost based vacuuming is disabled.

Under 8.0, if I run an update statement (update item
where set cost = cost + 0 where country = 'US' [causes
an update w/o really changing data]) that updates half
the rows in the table (~250k out of 500k - average
tuple width is about 500 bytes) and then execute a
regular vacuum it takes approximately 1400 seconds to
complete. A vacuum full performed immediately after
takes on the order of 2000 seconds to complete.

On Windows XP with 8.0beta1 I'm experiencing different
values instead, after updating 800K rows the plain vacuum
takes 200 seconds and the vacuum full immediately after
takes 620 seconds.

In both case the cpu usage was near zero.
I'm using a 2.2GHZ 1GB di RAM and I'm using 64MB to workmem.

Regards
Gaetano Mendola