problems with slow insert/delete queries/lot of disk write i/o in postgresql 7.2.4 - Mailing list pgsql-general

Hi,
We are having strange problem on production system with very slow
insert/delete commands and huge cpu and disk write activity spikes  in
postgresql 7.2.4. This behavior is very reproducible and happens in
following sequence :
1. full db vacuum
2. several hundred of insert/delete commands are performed as fast as
possible(tables used by insert/delete command are indexed to speed up
queries)


At (2) postgres starts taking 90-100% cpu and performing a lot of
writing that i guess flushing dirty buffers to disk and queries are
slowed down to nearly 1-2 per second. During this time postresql logs
'recycled transaction log ...' messages.
Postgres configuration is mostly default:
max_connections=45
shared_buffers=2048
deadlock_timeout = 60000
sort_mem = 1024
log_timestamp = true
log_pid = true
debug_level = 2

What causes postgres to behave like this? Is there anything can be
done to postgres [configuration] to handle bulk queries more efficient
and reduce disk i/o and cpu consumption?

Thanks a lot and sorry for long post,

alex.

Here's top and sar outputs during this time:
7:52am  up 42 days,  6:25,  1 user,  load average: 2.62, 1.90, 1.22
187 processes: 182 sleeping, 4 running, 1 zombie, 0 stopped
CPU states:  0.0% user, 80.7% system, 17.7% nice,  1.5% idle
Mem:  1025852K av, 1012012K used,   13840K free,       0K shrd,   20796K buff
Swap: 1026036K av,   23292K used, 1002744K free                  743360K cached

 PID USER     PRI  NI  SIZE  RSS SHARE STAT %CPU %MEM   TIME COMMAND
23411 postgres  17  10 19304  18M 18696 R N  84.1  1.8   7:16 postmaster
24177 admin     16   5  1044 1044   760 R N   6.6  0.1  17:39 top
11633 admin     17  10  5888 5888  1736 R N   6.1  0.5   0:00 ctl
321 admin      9   0     0    0     0 SW    0.6  0.0  19:30 kjournald


sar :
07:02:00          tps      rtps      wtps   bread/s   bwrtn/s
07:52:00        41.38      0.34     41.04     16.84    701.34
08:02:00        42.27      0.02     42.24      0.23    696.80
08:12:00        39.42      0.05     39.37      0.76    730.63

And sample of postmaster.log :

2005-06-24 07:53:24 [23411]  DEBUG:  StartTransactionCommand
2005-06-24 07:53:24 [23411]  DEBUG:  query: insert into MONITORING_DATA_LOC_DAIL
Y (MONITORING_DATA_LOC_DAILY_ID,GEN_ID,START_TIME,END_TIME,MONITORED_OBJECT_ID,L
OCATION_ID,TIME_SPAN,GAP_MILLIS,CE_COUNT,DATA) values (1,330861,1119398400000,11
19484800000,19011,19011,4,0,1,'6#|0#0#0#|311864#311864#0#0#0#0#0#0#0#0#0#0#0#0#0
#')
2005-06-24 07:53:24 [23411]  DEBUG:  ProcessQuery
2005-06-24 07:53:24 [23411]  DEBUG:  CommitTransactionCommand
2005-06-24 07:53:24 [23411]  DEBUG:  StartTransactionCommand
2005-06-24 07:53:24 [23411]  DEBUG:  query: delete from MONITORING_DATA_LOC_HOUR
LY where MONITORED_OBJECT_ID = cast(19011 as bigint) AND END_TIME <= cast(111948
4800000 as bigint)
2005-06-24 07:53:24 [23411]  DEBUG:  ProcessQuery
2005-06-24 07:53:25 [23411]  DEBUG:  CommitTransactionCommand
2005-06-24 07:53:25 [23411]  DEBUG:  StartTransactionCommand
2005-06-24 07:53:25 [23411]  DEBUG:  query: insert into MONITORING_DATA_LOC_DAIL
Y (MONITORING_DATA_LOC_DAILY_ID,GEN_ID,START_TIME,END_TIME,MONITORED_OBJECT_ID,L
OCATION_ID,TIME_SPAN,GAP_MILLIS,CE_COUNT,DATA) values (1,330861,1119398400000,11
19484800000,15877,15877,4,0,1,'7#|0#0#0#|121435#121435#0#0#0#0#0#0#0#0#0#0#0#0#0
#')
2005-06-24 07:53:25 [23411]  DEBUG:  ProcessQuery
2005-06-24 07:53:25 [23411]  DEBUG:  CommitTransactionCommand
2005-06-24 07:53:25 [23411]  DEBUG:  StartTransactionCommand
2005-06-24 07:53:25 [23411]  DEBUG:  query: delete from MONITORING_DATA_LOC_HOUR
LY where MONITORED_OBJECT_ID = cast(15877 as bigint) AND END_TIME <= cast(111948
4800000 as bigint)
2005-06-24 07:53:25 [23411]  DEBUG:  ProcessQuery
2005-06-24 07:53:26 [23411]  DEBUG:  CommitTransactionCommand
2005-06-24 07:53:26 [23411]  DEBUG:  StartTransactionCommand
2005-06-24 07:53:26 [23411]  DEBUG:  query: insert into MONITORING_DATA_LOC_DAIL
Y (MONITORING_DATA_LOC_DAILY_ID,GEN_ID,START_TIME,END_TIME,MONITORED_OBJECT_ID,L
OCATION_ID,TIME_SPAN,GAP_MILLIS,CE_COUNT,DATA) values (1,330861,1119398400000,11
19484800000,16095,16095,4,0,1,'6#|0#0#0#|78179338#78179338#0#0#0#0#0#0#0#0#0#0#0
#0#0#')
2005-06-24 07:53:26 [23411]  DEBUG:  ProcessQuery
2005-06-24 07:53:26 [23411]  DEBUG:  CommitTransactionCommand
2005-06-24 07:53:26 [11664]  DEBUG:  recycled transaction log file 0000000900000
0C5
2005-06-24 07:53:26 [11664]  DEBUG:  proc_exit(0)