very long updates very small tables

Dear list,

we have got a web application and when people log in some information is
written to the user tables. We have around 500 active users, but at the
most 5 people are logged in at the same time. From times to times people
log in and then the application is not responsive any more.

What we see in the postgres server logs is that processes are waiting
for other transactions to finish though not because of a deadlock.

The log tells me that certain update statements take sometimes about
3-10 minutes. But we are talking about updates on tables with 1000 to
10000 rows and updates that are supposed to update 1 row.

We are running under windows 2008 and postgres 8.4.7. ( Sorry for the
windows, it was not MY first choice )

My only explanation at the moment would be, that there must be any kind
of windows process that stops all other processes until it is finished
or something like that. ( Could it even be autovaccuum? ). Is there a
way to find out how long autovaccum took ? Has anyone seen anything
similiar? Or could it really be that we need a bigger machine with more
io? But the one disk in the system still seems not very busy and
response times in windows resource monitor are not higher than 28 ms.

Following is an excerpt of our server log.

LOG: process 1660 acquired ShareLock on transaction 74652 after
533354.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: process 4984 acquired ShareLock on transaction 74652 after
1523530.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: process 956 acquired ExclusiveLock on tuple (4,188) of relation
16412 of database 16384 after 383055.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: process 4312 acquired ExclusiveLock on tuple (9,112) of relation
16412 of database 16384 after 1422677.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: duration: 1523567.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '1362'
LOG: duration: 533391.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '31'
LOG: process 5504 acquired ExclusiveLock on tuple (9,112) of relation
16412 of database 16384 after 183216.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: process 1524 acquired ExclusiveLock on tuple (4,188) of relation
16412 of database 16384 after 376370.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: duration: 1422688.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '1362'
LOG: duration: 383067.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 'f', $2 = '31'
LOG: process 4532 acquired ExclusiveLock on tuple (9,112) of relation
16412 of database 16384 after 118851.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: process 4448 acquired ExclusiveLock on tuple (4,188) of relation
16412 of database 16384 after 366304.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: duration: 183241.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '1362'
LOG: duration: 376395.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '31'
LOG: process 4204 acquired ExclusiveLock on tuple (4,188) of relation
16412 of database 16384 after 339893.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: duration: 366342.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '31'
LOG: process 4760 acquired ExclusiveLock on tuple (4,188) of relation
16412 of database 16384 after 205943.000 ms
STATEMENT: UPDATE extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
LOG: duration: 339923.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '31'
LOG: duration: 205963.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '31'
LOG: duration: 124654.000 ms execute <unnamed>: UPDATE
extjs_recentlist SET visible=$1 WHERE recentlist_id=$2
DETAIL: parameters: $1 = 't', $2 = '1362'
LOG: process 3844 still waiting for ShareLock on transaction 74839
after 8000.000 ms

Thanx in advance.

Lars
--
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Lars Feistner

Kompetenzzentrum für Prüfungen in der Medizin
Medizinische Fakultät Heidelberg,
Im Neuenheimer Feld 346, Raum 013
69120 Heidelberg

E-Mail: feistner(at)uni-heidelberg(dot)de
Fon: +49-6221-56-8269
Fax: +49-6221-56-7175

WWW: http://www.ims-m.de
http://www.kompmed.de
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~