very long updates very small tables

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@xxxxxxxxxxxxxxxxx
Fon:   +49-6221-56-8269
Fax:   +49-6221-56-7175

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

--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance


[Postgresql General]     [Postgresql PHP]     [PHP Users]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Yosemite]

  Powered by Linux