problems with slow insert/delete queries/lot of disk write i/o in postgresql 7.2.4

From: Alexander Korobov <akorobov(at)gmail(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: problems with slow insert/delete queries/lot of disk write i/o in postgresql 7.2.4
Date: 2005-06-27 17:35:12
Message-ID: f235ad3805062710356e4a267c@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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)

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Andreas 2005-06-27 17:52:44 Re: DANGER Windows version might hurt you
Previous Message ben.hallert 2005-06-27 17:30:38 Generate a list of (days/hours) between two dates