autovacuum: 50% iowait for hours - Mailing list pgsql-general

Hello all,

I have a hard situation in hands. my autovacuum does not seem to be able
to get his job done;

database is under active INSERTs/UPDATEs;
CPU is in aprox 50% iowait for the past 5 hours;

I've tried turning off autovacuum and the effect goes away; I turn it back
on and it goes back to 50% iowait; my IO system is nothing special at all;

besides turning autovacuum off and running vacuum by hand once in a while,
what else can I do to get out of this situation ?

bellow some logs

I'm seriously considering turning off autovacuum for good; but I'dd like
to get input concerning other approaches... I mean... if I don't turn it
of, how can I be sure this will not happen again... we ship products with
PG inside... I must be absolutelly sure this will not ever happen in any of
our costumers. I'm a bit confuse... sorry :) !

Joao

============================================
2010-05-13 20:55:00 WEST   DEBUG:  server process (PID 6197) exited with
exit code 0
2010-05-13 20:55:00 WEST   DEBUG:  forked new backend, pid=6573 socket=6
2010-05-13 20:57:41 WEST   ERROR:  failed to re-find parent key in
"timeslots_strs_var_ts_key"
2010-05-13 20:58:42 WEST   LOG:  autovacuum: processing database
"postgres"
2010-05-13 20:59:35 WEST   DEBUG:  checkpoint starting
2010-05-13 20:59:35 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 20:59:42 WEST   LOG:  autovacuum: processing database
"template1"
2010-05-13 21:00:00 WEST   DEBUG:  server process (PID 6573) exited with
exit code 0
2010-05-13 21:00:00 WEST   DEBUG:  forked new backend, pid=6846 socket=6
2010-05-13 21:01:00 WEST   LOG:  autovacuum: processing database "egbert"
2010-05-13 21:01:00 WEST   DEBUG:  autovac: will VACUUM ANALYZE timeslots
2010-05-13 21:01:00 WEST   DEBUG:  vacuuming "public.timeslots"
2010-05-13 21:02:39 WEST   DEBUG:  index "timeslots_timestamp_index" now
contains 3971156 row versions in 15338 pages
2010-05-13 21:02:39 WEST   DETAIL:  351 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.67s/1.28u sec elapsed 71.06 sec.
2010-05-13 21:03:51 WEST   DEBUG:  index "timeslots_timeslot_index" now
contains 3971159 row versions in 18724 pages
2010-05-13 21:03:51 WEST   DETAIL:  351 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.86s/1.31u sec elapsed 71.65 sec.
2010-05-13 21:04:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:04:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:04:58 WEST   DEBUG:  index "timeslots_var_index" now
contains 3971167 row versions in 23857 pages
2010-05-13 21:04:58 WEST   DETAIL:  351 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 1.34s/1.36u sec elapsed 67.49 sec.
2010-05-13 21:05:00 WEST   DEBUG:  server process (PID 6846) exited with
exit code 0
2010-05-13 21:05:01 WEST   DEBUG:  forked new backend, pid=7319 socket=6
2010-05-13 21:09:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:09:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:10:08 WEST   DEBUG:  server process (PID 7319) exited with
exit code 0
2010-05-13 21:10:08 WEST   DEBUG:  forked new backend, pid=7845 socket=6
2010-05-13 21:14:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:14:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:15:00 WEST   DEBUG:  server process (PID 7845) exited with
exit code 0
2010-05-13 21:15:00 WEST   DEBUG:  forked new backend, pid=8214 socket=6
2010-05-13 21:19:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:19:41 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:20:00 WEST   DEBUG:  server process (PID 8214) exited with
exit code 0
2010-05-13 21:20:00 WEST   DEBUG:  forked new backend, pid=8521 socket=6
2010-05-13 21:24:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:24:38 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:25:00 WEST   DEBUG:  server process (PID 8521) exited with
exit code 0
2010-05-13 21:25:00 WEST   DEBUG:  forked new backend, pid=8919 socket=6
2010-05-13 21:29:37 WEST   DEBUG:  checkpoint starting
2010-05-13 21:29:40 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:30:00 WEST   DEBUG:  server process (PID 8919) exited with
exit code 0
2010-05-13 21:30:00 WEST   DEBUG:  forked new backend, pid=9239 socket=6
2010-05-13 21:34:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:34:38 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:35:00 WEST   DEBUG:  server process (PID 9239) exited with
exit code 0
2010-05-13 21:35:00 WEST   DEBUG:  forked new backend, pid=9672 socket=6
2010-05-13 21:39:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:39:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:40:00 WEST   DEBUG:  server process (PID 9672) exited with
exit code 0
2010-05-13 21:40:00 WEST   DEBUG:  forked new backend, pid=9979 socket=6
2010-05-13 21:44:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:44:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:44:59 WEST   ERROR:  failed to re-find parent key in
"timeslots_strs_var_ts_key"
2010-05-13 21:45:00 WEST   DEBUG:  server process (PID 9979) exited with
exit code 0
2010-05-13 21:45:00 WEST   DEBUG:  forked new backend, pid=10340 socket=6
2010-05-13 21:46:00 WEST   LOG:  autovacuum: processing database
"postgres"
2010-05-13 21:47:00 WEST   LOG:  autovacuum: processing database
"template1"
2010-05-13 21:48:01 WEST   LOG:  autovacuum: processing database "egbert"
2010-05-13 21:48:01 WEST   DEBUG:  autovac: will VACUUM ANALYZE timeslots
2010-05-13 21:48:01 WEST   DEBUG:  vacuuming "public.timeslots"
2010-05-13 21:49:30 WEST   DEBUG:  index "timeslots_timestamp_index" now
contains 3971435 row versions in 15340 pages
2010-05-13 21:49:30 WEST   DETAIL:  405 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.78s/1.23u sec elapsed 63.81 sec.
2010-05-13 21:49:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:49:37 WEST   DEBUG:  removing file "pg_subtrans/00AE"
2010-05-13 21:49:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:50:00 WEST   DEBUG:  server process (PID 10340) exited with
exit code 0
2010-05-13 21:50:01 WEST   DEBUG:  forked new backend, pid=10642 socket=6
2010-05-13 21:50:47 WEST   DEBUG:  index "timeslots_timeslot_index" now
contains 3971451 row versions in 18726 pages
2010-05-13 21:50:47 WEST   DETAIL:  405 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.88s/1.32u sec elapsed 76.99 sec.
2010-05-13 21:51:56 WEST   DEBUG:  index "timeslots_var_index" now
contains 3971471 row versions in 23861 pages
2010-05-13 21:51:56 WEST   DETAIL:  405 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 1.10s/1.40u sec elapsed 69.38 sec.
2010-05-13 21:54:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:54:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 21:55:00 WEST   DEBUG:  server process (PID 10642) exited with
exit code 0
2010-05-13 21:55:00 WEST   DEBUG:  forked new backend, pid=11061 socket=6
2010-05-13 21:59:35 WEST   DEBUG:  checkpoint starting
2010-05-13 21:59:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:00:00 WEST   DEBUG:  server process (PID 11061) exited with
exit code 0
2010-05-13 22:00:01 WEST   DEBUG:  forked new backend, pid=11398 socket=6
2010-05-13 22:04:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:04:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:05:00 WEST   DEBUG:  forked new backend, pid=11725 socket=6
2010-05-13 22:05:00 WEST   DEBUG:  server process (PID 11398) exited with
exit code 0
2010-05-13 22:09:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:09:39 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:10:00 WEST   DEBUG:  server process (PID 11725) exited with
exit code 0
2010-05-13 22:10:00 WEST   DEBUG:  forked new backend, pid=12073 socket=6
2010-05-13 22:14:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:14:39 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:15:00 WEST   DEBUG:  forked new backend, pid=12328 socket=6
2010-05-13 22:15:00 WEST   DEBUG:  server process (PID 12073) exited with
exit code 0
2010-05-13 22:19:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:19:38 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:20:00 WEST   DEBUG:  server process (PID 12328) exited with
exit code 0
2010-05-13 22:20:00 WEST   DEBUG:  forked new backend, pid=12601 socket=6
2010-05-13 22:24:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:24:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:25:02 WEST   DEBUG:  server process (PID 12601) exited with
exit code 0
2010-05-13 22:25:02 WEST   DEBUG:  forked new backend, pid=12864 socket=6
2010-05-13 22:29:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:29:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:30:00 WEST   DEBUG:  server process (PID 12864) exited with
exit code 0
2010-05-13 22:30:00 WEST   DEBUG:  forked new backend, pid=13109 socket=6
2010-05-13 22:31:29 WEST   ERROR:  failed to re-find parent key in
"timeslots_strs_var_ts_key"
2010-05-13 22:32:29 WEST   LOG:  autovacuum: processing database
"postgres"
2010-05-13 22:33:29 WEST   LOG:  autovacuum: processing database
"template1"
2010-05-13 22:34:29 WEST   LOG:  autovacuum: processing database "egbert"
2010-05-13 22:34:29 WEST   DEBUG:  autovac: will VACUUM ANALYZE timeslots
2010-05-13 22:34:29 WEST   DEBUG:  vacuuming "public.timeslots"
2010-05-13 22:34:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:34:36 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:35:00 WEST   DEBUG:  server process (PID 13109) exited with
exit code 0
2010-05-13 22:35:00 WEST   DEBUG:  forked new backend, pid=13329 socket=6
2010-05-13 22:36:06 WEST   DEBUG:  index "timeslots_timestamp_index" now
contains 3971652 row versions in 15341 pages
2010-05-13 22:36:06 WEST   DETAIL:  321 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.81s/1.24u sec elapsed 72.89 sec.
2010-05-13 22:37:16 WEST   DEBUG:  index "timeslots_timeslot_index" now
contains 3971652 row versions in 18727 pages
2010-05-13 22:37:16 WEST   DETAIL:  321 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 0.97s/1.35u sec elapsed 69.51 sec.
2010-05-13 22:38:27 WEST   DEBUG:  index "timeslots_var_index" now
contains 3971656 row versions in 23861 pages
2010-05-13 22:38:27 WEST   DETAIL:  321 index row versions were removed.
    0 index pages have been deleted, 0 are currently reusable.
    CPU 1.39s/1.43u sec elapsed 70.76 sec.
2010-05-13 22:39:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:39:38 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:40:00 WEST   DEBUG:  server process (PID 13329) exited with
exit code 0
2010-05-13 22:40:00 WEST   DEBUG:  forked new backend, pid=13549 socket=6
2010-05-13 22:44:36 WEST   DEBUG:  checkpoint starting
2010-05-13 22:44:45 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:45:00 WEST   DEBUG:  server process (PID 13549) exited with
exit code 0
2010-05-13 22:45:00 WEST   DEBUG:  forked new backend, pid=13918 socket=6
2010-05-13 22:49:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:49:38 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:50:01 WEST   DEBUG:  server process (PID 13918) exited with
exit code 0
2010-05-13 22:50:01 WEST   DEBUG:  forked new backend, pid=14218 socket=6
2010-05-13 22:50:22 WEST   DEBUG:  forked new backend, pid=14278 socket=6
2010-05-13 22:51:11 WEST   DEBUG:  server process (PID 14278) exited with
exit code 0
2010-05-13 22:51:20 WEST   DEBUG:  forked new backend, pid=14368 socket=6
2010-05-13 22:51:22 WEST   DEBUG:  server process (PID 14368) exited with
exit code 0
2010-05-13 22:52:52 WEST   DEBUG:  forked new backend, pid=14516 socket=6
2010-05-13 22:52:52 WEST   DEBUG:  server process (PID 14516) exited with
exit code 0
2010-05-13 22:54:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:54:37 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 22:55:00 WEST   DEBUG:  server process (PID 14218) exited with
exit code 0
2010-05-13 22:55:00 WEST   DEBUG:  forked new backend, pid=14775 socket=6
2010-05-13 22:59:35 WEST   DEBUG:  checkpoint starting
2010-05-13 22:59:40 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 23:00:01 WEST   DEBUG:  server process (PID 14775) exited with
exit code 0
2010-05-13 23:00:01 WEST   DEBUG:  forked new backend, pid=15443 socket=6
2010-05-13 23:04:35 WEST   DEBUG:  checkpoint starting
2010-05-13 23:04:43 WEST   DEBUG:  checkpoint complete; 0 transaction log
file(s) added, 0 removed, 0 recycled
2010-05-13 23:05:00 WEST   DEBUG:  forked new backend, pid=16028 socket=6
2010-05-13 23:05:00 WEST   DEBUG:  server process (PID 15443) exited with
exit code 0