Thread: Postgresql 8.0 beta 1 - strange cpu usage statistics and slow vacuuming
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.item" 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
Shelby Cain <alyandon@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
--- Tom Lane <tgl@sss.pgh.pa.us> wrote: > > > 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. > I'm pretty certain. Here are my settings: vacuum_cost_delay = 0 # 0-1000 milliseconds vacuum_cost_page_hit = 1 # 0-10000 credits vacuum_cost_page_miss = 10 # 0-10000 credits vacuum_cost_page_dirty = 20 # 0-10000 credits vacuum_cost_limit = 200 # 0-10000 credits From looking at vacuum.c I gathered vacuum_cost_delay must be >0 to enable the feature - correct? Regards, Shelby Cain __________________________________ Do you Yahoo!? Yahoo! Mail - 50x more storage than other providers! http://promotions.yahoo.com/new_mail
Shelby Cain <alyandon@yahoo.com> writes:
> From looking at vacuum.c I gathered vacuum_cost_delay
> must be >0 to enable the feature - correct?
Yeah, that's right --- delay=0 turns it off. Weird. Can anyone else
reproduce the problem?
regards, tom lane
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.item" > 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
--- Tom Lane <tgl@sss.pgh.pa.us> wrote: > Shelby Cain <alyandon@yahoo.com> writes: > > From looking at vacuum.c I gathered > vacuum_cost_delay > > must be >0 to enable the feature - correct? > > Yeah, that's right --- delay=0 turns it off. Weird. > Can anyone else > reproduce the problem? > On a hunch, I turned fsync off and the performance jumped up to around the same performance I was getting running the cygwin 7.4.x port. The system is a IBM Netvista (P4 2.0 ghz w/256 megs of ram, IDE drive) running Windows 2000 SP4. I've attached a minimal test script that should reproduce the issue. However, please be aware that I've yet to reproduce this issue on XP Pro SP 1 (p4-2.8G, 1g ram, IDE drive). I'll try and see if I can reproduce this on other systems and get back to the list. If anyone has access to Windows 2000 SP4 and wants to run this test script I'd be very interested in hearing your results. Regards, Shelby Cain __________________________________ Do you Yahoo!? Yahoo! Mail Address AutoComplete - You start. We finish. http://promotions.yahoo.com/new_mail drop table test1; CREATE TABLE test1 ( idnbr integer unique not null, num1 numeric(12,2), num2 numeric(12,2), text1 varchar(600) ); create function fill_table(integer) returns integer as ' DECLARE maxnum alias for $1; md5str text; startid integer; BEGIN select coalesce(max(idnbr)+1,0) from test1 into startid; for i in 1..maxnum loop select substr( md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()) ||md5(random()), 1,(200+random()*400)::integer ) into md5str; insert into test1 values (startid+i,random()*10000, (random()*100)::integer, md5str); end loop; return maxnum; END; ' language plpgsql; truncate test1; select fill_table(100000); analyze test1; update test1 set num1 = num1 + 0 where random() > 0.5; -- These shouldn't take long at all for a table containing 100000 tuples + ~50000 dead tuples vacuum verbose test1; vacuum full verbose test1;
Shelby Cain <alyandon@yahoo.com> writes:
> On a hunch, I turned fsync off and the performance
> jumped up to around the same performance I was getting
> running the cygwin 7.4.x port.
Ah-hah. The win32 hackers should confirm this, but my recollection is
that sync/fsync are no-ops under Cygwin (one of the several reasons
we would never recommend that port for production use). So this would
fit the assumption that the 7.4 code was simply not syncing.
regards, tom lane
--- Tom Lane <tgl@sss.pgh.pa.us> wrote: > Ah-hah. The win32 hackers should confirm this, but > my recollection is > that sync/fsync are no-ops under Cygwin (one of the > several reasons > we would never recommend that port for production > use). So this would > fit the assumption that the 7.4 code was simply not > syncing. > Sounds reasonable. However, I don't see the same performance hit while doing bulk database operations (ie: inserts, deletes, updates). Is that expected behavior? Do vacuum operations fsync()/_commit() more often? Regards, Shelby Cain __________________________________ Do you Yahoo!? New and Improved Yahoo! Mail - 100MB free storage! http://promotions.yahoo.com/new_mail
Shelby Cain <alyandon@yahoo.com> writes:
> Sounds reasonable. However, I don't see the same
> performance hit while doing bulk database operations
> (ie: inserts, deletes, updates). Is that expected
> behavior? Do vacuum operations fsync()/_commit() more
> often?
IIRC, vacuum fsyncs once per table (possibly more depending on whether
you add FULL, ANALYZE, etc). Not clear what case you are considering
exactly.
regards, tom lane
Shelby Cain wrote: > --- Tom Lane <tgl@sss.pgh.pa.us> wrote: > >>Ah-hah. The win32 hackers should confirm this, but >>my recollection is >>that sync/fsync are no-ops under Cygwin (one of the >>several reasons >>we would never recommend that port for production >>use). So this would >>fit the assumption that the 7.4 code was simply not >>syncing. >> > > > Sounds reasonable. However, I don't see the same > performance hit while doing bulk database operations > (ie: inserts, deletes, updates). Is that expected > behavior? Do vacuum operations fsync()/_commit() more > often? I think you have other problems around, see the post where I did some tests. Regards Gaetano Mendola
--- Tom Lane <tgl@sss.pgh.pa.us> wrote: > IIRC, vacuum fsyncs once per table (possibly more > depending on whether > you add FULL, ANALYZE, etc). Not clear what case > you are considering > exactly. > Vacuum and Vacuum full. The script I attached to a previous post to demonstrate the behavior (at least on this workstation) creates and populates a single table via a stored procedure, updates approximately half the rows and then executes a vacuum followed by a vacuum full. The insert and update commands execute far faster (showing 5-10 megs of disk transfer per second on average) than both the vacuum and vacuum full (showing 512k to 1meg of transfer per second). Regards, Shelby Cain __________________________________ Do you Yahoo!? Yahoo! Mail Address AutoComplete - You start. We finish. http://promotions.yahoo.com/new_mail