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

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

From
Shelby Cain
Date:
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

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

From
Shelby Cain
Date:
--- 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

Re: Postgresql 8.0 beta 1 - strange cpu usage statistics and slow

From
Gaetano Mendola
Date:
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







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

From
Shelby Cain
Date:
--- 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

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

From
Shelby Cain
Date:
--- 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

Re: Postgresql 8.0 beta 1 - strange cpu usage statistics and slow

From
Gaetano Mendola
Date:
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



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

From
Shelby Cain
Date:
--- 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