Thread: blocking automatic vacuum

Hi,

last ween i've seen a blocking "automatic vacuum".
as i understood, this is not supposed to happen. in the past i saw vacuum processes disappear, in case of the need of a lock.


this is the relvant extract from the log and the database:
2010-06-18 18:33:36.011 CEST    172.19.5.34(57414)      gc:29274        143897560       LOG:  process 29274 still waiting for RowExclusiveLock on relation 42964239 of database 19759903 after 1002.601 ms
...
2010-06-18 19:23:43.898 CEST            :20892  0       LOG:  automatic vacuum of table "gd.pg_toast.pg_toast_42964236": index scans: 1
        pages: 1469113 removed, 288899 remain
        tuples: 369645 removed, 396719 remain
        system usage: CPU 5.46s/0.85u sec elapsed 13785.76 sec
2010-06-18 19:23:43.899 CEST    172.19.5.22(45561)      gc:315  143897590       LOG:  process 315 acquired RowExclusiveLock on relation 42964239 of database 19759903 after 3007903.169 ms
2010-06-18 19:23:43.920 CEST    172.19.5.22(45561)      gc:315  143897590       LOG:  duration: 3007924.883 ms  execute <unnamed>: insert into SHARED_GAMESET .....

gd=# select oid,* from pg_class where reltoastrelid=42964239;
    relname     | relnamespace | reltype  | relowner | relam | relfilenode | reltablespace | relpages |  reltuples  | reltoastrelid | reltoastidxid | relhasindex | relisshared | relistemp | relkind | relnatts | relchecks | rel
hasoids | relhaspkey | relhasrules | relhastriggers | relhassubclass | relfrozenxid |                 relacl                 | reloptions
----------------+--------------+----------+----------+-------+-------------+---------------+----------+-------------+---------------+---------------+-------------+-------------+-----------+---------+----------+-----------+----
--------+------------+-------------+----------------+----------------+--------------+----------------------------------------+------------
 shared_gameset |     19760303 | 42964238 |    16443 |     0 |    42964236 |             0 |   143715 | 1.96642e+06 |      42964239 |             0 | t           | f           | f         | r       |        4 |         0 | f 
        | t          | f           | f              | f              |    101290258 | {gdadm=arwdDxt/gdadm,gc=arwdDxt/gdadm} |
(1 row)



So what's this?
from my point of view the vacuum blocked inserts on this table for about 50 minutes.
Is this a bug?
Or do yuo see here a configuration issue?

best regards,
Uwe

Uwe Bartels
Systemarchitect - Freelancer
mailto: uwe.bartels at gmail.com

Uwe Bartels <uwe.bartels@gmail.com> wrote:

> last ween i've seen a blocking "automatic vacuum".

What does SELECT version(); show?

-Kevin

# select version();
                                                     version                                                     
------------------------------------------------------------------------------------------------------------------
 PostgreSQL 8.4.3 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC) 4.1.2 20071124 (Red Hat 4.1.2-42), 64-bit
(1 row)

Uwe Bartels <uwe.bartels@gmail.com> writes:
> last ween i've seen a blocking "automatic vacuum".
> as i understood, this is not supposed to happen. in the past i saw vacuum
> processes disappear, in case of the need of a lock.

What that sounds like is it was an anti-wraparound vacuum.  Autovacuum
won't cancel those to avoid delaying other processes.

Now, RowExclusiveLock doesn't conflict with an autovacuum, so there is
more going on here than you've showed us.  The other obvious question is
how did you get to the point where an anti-wraparound vacuum became
necessary.

I speculate that you are doing something that does conflict with vacuum
(ie, SHARE UPDATE EXCLUSIVE lock or higher), and are doing it so often
that regular autovacuum runs on the table never manage to complete.
This is very bad, because you're going to have a serious bloat problem
if autovac keeps getting canceled.  You need to look at what sort of DDL
you are repetitively executing on that table, and find a way to do it a
lot less often.

            regards, tom lane

Hi Tom,

hmm. thanks for your answer.
i'm pretty sure there is no repetitive ddl happen on this or any other table. i checked this with the developers.

but if i had an anti-wraparound vacuum, then i should see warnings like these in the log. am i right? I don't have any warnings that day.

WARNING:  database "mydb" must be vacuumed within 177009986 transactions
HINT:  To avoid a database shutdown, execute a database-wide VACUUM in "mydb".

the table shared_gameset belonging to the vacuumed table pg_toast.pg_toast_42964236 is new and exists only for about one month.

the table was also vacuumed the day before.
2010-06-17 20:20:41.044 CEST            :16787  0       LOG:  automatic vacuum of table "gd.pg_toast.pg_toast_42964236": index scans: 1
        pages: 0 removed, 1758012 remain
        tuples: 718132 removed, 703020 remain
        system usage: CPU 0.02s/0.01u sec elapsed 12354.51 sec

other statements on that table are
- delete ... where timstamp < ....
- select * from ....
but, that's it.

If you wish i can send you the complete log for that day.

best regards,
Uwe

Uwe Bartels <uwe.bartels@gmail.com> writes:
> i'm pretty sure there is no repetitive ddl happen on this or any other
> table. i checked this with the developers.

Well, *something* was blocking that RowExclusiveLock request, and for
sure it wasn't autovacuum.  There has to be something else going on.

> but if i had an anti-wraparound vacuum, then i should see warnings like
> these in the log. am i right? I don't have any warnings that day.

> WARNING:  database "mydb" must be vacuumed within 177009986 transactions
> HINT:  To avoid a database shutdown, execute a database-wide VACUUM in "mydb".

Uh, no.  Anti-wraparound vacuums are performed long before you would get
to the point of seeing any actual warnings.

            regards, tom lane

Hi Tom,

till now i found more blocking vacuum processes in other databases as well.
we migrated postgres from 8.3 to 8.4 in april.

on most databases we have slony running - they have a good potential for getting to that high number of transactions. only that they do their own vacuum on the most frequented tables.
what exactly happens during anti-wraparond vacuum in terms of locking and for how long?

best regards,
Uwe

Excerpts from Uwe Bartels's message of jue jul 01 04:42:42 -0400 2010:
> Hi Tom,
>
> till now i found more blocking vacuum processes in other databases as well.
> we migrated postgres from 8.3 to 8.4 in april.

Please examine pg_locks to see what's blocking autovacuum.  The key is
WHERE granted=f.