DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta;
	h=received:message-id:date:from:to:subject:mime-version:content-type;
	b=lmxvDjeATqvFYpsolLJFcFrLplCS0dorXJci9y38EFdstRU5mit3jZW68umrtWKSm3pTK0pMKfzf13GdBRqr56gt1pCkRzuQPE0iA5mepTDrhHtFaaVZ0T12UQ87yiLkRCmZ6Hkm2VdZRb/Wl/vRVoiR9KIZ4lu4MrMU4mwZKIY=
Message-ID: <357fa7590707271432l709da359n68deea693d2c5fdf@mail.gmail.com>
Date: Fri, 27 Jul 2007 17:32:11 -0400
From: "Steven Flatt" <steven.flatt@gmail.com>
To: pgsql-performance@postgresql.org
Subject: Vacuum looping?
MIME-Version: 1.0
Content-Type: multipart/alternative;
	boundary="----=_Part_11421_18731775.1185571931220"

------=_Part_11421_18731775.1185571931220
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

Postgres 8.2.4.

We have a large table, let's call it "foo", whereby an automated process
periodically inserts many (hundreds of thousands or millions) rows into it
at a time.  It's essentially INSERT INTO foo SELECT FROM <another table>
WHERE <some conditions>.  Recently, for whatever reason, the query started
to run out of memory.  This happened on the order of 50 times before it was
noticed and the process was stopped.  (Admittedly, more investigation needs
to go into the OOM problem... )

Now autovacuum promptly kicked in trying to clean up this mess, however it
couldn't keep up at the rate that dead tuples were being generated.  I'm not
sure if it got into a weird state.  After a few days, long after the
inserting process was stopped, we decided to abort the vacuum (which we
weren't convinced was doing anything), then start a manual vacuum with a
higher vacuum_cost_limit to get things cleaned up quicker.

After 28 hours, here was the output of vacuum verbose:

# VACUUM VERBOSE foo;
INFO:  vacuuming "public.foo"
INFO:  scanned index "foo_pkey" to remove 44739062 row versions
DETAIL:  CPU 5.74s/26.09u sec elapsed 529.57 sec.
INFO:  scanned index "foo_1" to remove 44739062 row versions
DETAIL:  CPU 760.09s/619.83u sec elapsed 56929.54 sec.
INFO:  scanned index "foo_2" to remove 44739062 row versions
DETAIL:  CPU 49.35s/99.57u sec elapsed 4410.74 sec.
INFO:  "foo": removed 44739062 row versions in 508399 pages
DETAIL:  CPU 47.35s/12.88u sec elapsed 3985.92 sec.
INFO:  scanned index "foo_pkey" to remove 32534234 row versions
DETAIL:  CPU 22.05s/32.51u sec elapsed 2259.05 sec.

The vacuum then just sat there.  What I can't understand is why it went back
for a second pass of the pkey index?  There was nothing writing to the table
once the vacuum began.  Is this behaviour expected?  Are these times
reasonable for a vacuum (on a busy system, mind you)?

We have since aborted the vacuum and truncated the table.  We're now working
on the root OOM problem, which is easier said than done...

Steve

------=_Part_11421_18731775.1185571931220
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

<div>Postgres 8.2.4.</div>
<div>&nbsp;</div>
<div>We have a large table, let&#39;s call it &quot;foo&quot;, whereby an automated process periodically inserts many (hundreds of thousands or millions) rows into it at a time.&nbsp; It&#39;s essentially INSERT INTO foo SELECT FROM &lt;another table&gt; WHERE &lt;some conditions&gt;.&nbsp; Recently, for whatever reason, the query started to run out of memory.&nbsp; This happened on the order of 50 times before it was noticed and the process was stopped.&nbsp; (Admittedly, more investigation needs to go into the OOM problem... )
</div>
<div>&nbsp;</div>
<div>Now autovacuum promptly kicked in trying to clean up this mess, however it couldn&#39;t keep up at the rate that dead tuples were being generated.&nbsp; I&#39;m not sure if it got into a weird state.&nbsp; After a few days, long after the inserting process was stopped,&nbsp;we decided to abort the vacuum (which we weren&#39;t convinced was doing anything), then start a manual vacuum with a higher vacuum_cost_limit to get things cleaned up quicker.
</div>
<div>&nbsp;</div>
<div>After 28 hours, here was the output of vacuum verbose:</div>
<div>&nbsp;</div>
<div># VACUUM VERBOSE foo;<br>INFO:&nbsp; vacuuming &quot;public.foo&quot;<br>INFO:&nbsp; scanned index &quot;foo_pkey&quot; to remove 44739062 row versions<br>DETAIL:&nbsp; CPU 5.74s/26.09u sec elapsed 529.57 sec.<br>INFO:&nbsp; scanned index &quot;foo_1&quot; to remove 44739062 row versions
<br>DETAIL:&nbsp; CPU 760.09s/619.83u sec elapsed 56929.54 sec.<br>INFO:&nbsp; scanned index &quot;foo_2&quot; to remove 44739062 row versions<br>DETAIL:&nbsp; CPU 49.35s/99.57u sec elapsed 4410.74 sec.<br>INFO:&nbsp; &quot;foo&quot;: removed 44739062 row versions in 508399 pages
<br>DETAIL:&nbsp; CPU 47.35s/12.88u sec elapsed 3985.92 sec.<br>INFO:&nbsp; scanned index &quot;foo_pkey&quot; to remove 32534234 row versions<br>DETAIL:&nbsp; CPU 22.05s/32.51u sec elapsed 2259.05 sec.<br>&nbsp;</div>
<div>The vacuum then just sat there.&nbsp; What I can&#39;t understand is why it went back for a second pass of the pkey index?&nbsp; There was nothing writing to the table once the vacuum began.&nbsp; Is this behaviour expected?&nbsp; Are these times reasonable for a vacuum (on a busy system, mind you)?
</div>
<div>&nbsp;</div>
<div>We have since aborted the vacuum and truncated the table.&nbsp; We&#39;re now working on the root OOM problem, which is easier said than done...</div>
<div>&nbsp;</div>
<div>Steve</div>
<div>&nbsp;</div>

------=_Part_11421_18731775.1185571931220--