"Hanging Connection" blocks access to table (JBossMQ)

I'm running Postgresql 8.1.4 on Redhat ES 4.0. Jboss 4.0.3 is running on a
separate server. I'm using the "Version 8.1-407" jdbc driver.

I'm running autovacuum and everything was working well for a couple of
weeks, but it appears that it has slowed the database to a point where a db
insert of a large (5MB -10MB) record takes too long in Jboss and Jboss
aborts the transaction.

Even more of a problem is that the postgres process/connection does not
close. Instead it holds the lock indefinitely. Killing Jboss does not even
free the connections. Only a restart of postgresql does the job (though
there may be a way to close it without a postgres restart).

Turning off autovacuum seems to resolve the problem, or at least prevents it
from happening with the current load. This is a problem though since my
application runs 7x24 and I was hoping to avoid large vacuum pauses through
the use of autovacuum. Besides, as my tables grow, I may cross some
threshold where it begins to happen again, but can't be fixed as easily as
turning off autovacuum.

The server doesn't seem to be under exceptional load with autovacuum. My
load number are 1.0 1.0 1.0 with autovacuum and .2 .2 .2 without. I've got
logging set and there are no errors or warnings in the pg logifles.

There is a mention in the 8.1-406 changelog about a fix for an
OutOfMemoryError preventing the caller from closing a connection. Could
autovacuum be using enough memory so that postgres cannot handle the insert
of the large row?

Thanks,

Mike

Here is some logging info around the time of a lock:

[9908-jbossdb-jboss-2006-10-11 00:05:31.791 EDT]LOG: duration: 799.254 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9914---2006-10-11 00:06:31.855 EDT]LOG: autovacuum: processing database
"template1"
[9915---2006-10-11 00:07:31.860 EDT]LOG: autovacuum: processing database
"jbossdb"
[9916---2006-10-11 00:08:31.869 EDT]LOG: autovacuum: processing database
"template1"
[9917---2006-10-11 00:09:31.875 EDT]LOG: autovacuum: processing database
"jbossdb"
[9921---2006-10-11 00:10:31.884 EDT]LOG: autovacuum: processing database
"template1"
[9922---2006-10-11 00:11:31.890 EDT]LOG: autovacuum: processing database
"jbossdb"
[9923---2006-10-11 00:12:31.899 EDT]LOG: autovacuum: processing database
"template1"
[9924---2006-10-11 00:13:31.905 EDT]LOG: autovacuum: processing database
"jbossdb"
[9925---2006-10-11 00:14:31.914 EDT]LOG: autovacuum: processing database
"template1"
[9926---2006-10-11 00:15:31.920 EDT]LOG: autovacuum: processing database
"jbossdb"
[9908-jbossdb-jboss-2006-10-11 00:15:47.372 EDT]LOG: duration: 804.596 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9909-jbossdb-jboss-2006-10-11 00:16:03.353 EDT]LOG: duration: 602.770 ms
statement: EXECUTE <unnamed> [PREPARE: UPDATE JMS_MESSAGES SET TXID=$1,
TXOP=$2 WHERE MESSAGEID=$3 AND DESTINATION=$4]
[9913-jbossdb-jboss-2006-10-11 00:16:11.353 EDT]LOG: duration: 681.207 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9927---2006-10-11 00:16:31.928 EDT]LOG: autovacuum: processing database
"template1"
[9913-jbossdb-jboss-2006-10-11 00:16:43.409 EDT]LOG: duration: 654.744 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9909-jbossdb-jboss-2006-10-11 00:16:47.380 EDT]LOG: duration: 802.873 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9928---2006-10-11 00:17:31.934 EDT]LOG: autovacuum: processing database
"jbossdb"
[9912-jbossdb-jboss-2006-10-11 00:18:08.372 EDT]LOG: duration: 812.530 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO instance (pk, url,
storageCommited, instanceNumber, contentDatetime, rows, cols, bitsAllocated,
numberOfFrames, prLabel, prDescription, prCreationDatetime, prCreatorName,
completionFlag, completionFlagDescription, verificationFlag,
observationDatetime, hidden, purged, version, dataset, associationID,
srcode_fk, sop_fk, series_fk) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9,
$10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22, $23, $24,
$25)]
[9930-jbossdb-jboss-2006-10-11 00:18:31.364 EDT]LOG: duration: 677.751 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9912-jbossdb-jboss-2006-10-11 00:19:19.409 EDT]LOG: duration: 567.697 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO JMS_MESSAGES
(MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES($1,$2,$3,$4,$5)]
[9943-jbossdb-jboss-2006-10-11 01:11:32.243 EDT]LOG: duration: 836.010 ms
statement: EXECUTE <unnamed> [PREPARE: INSERT INTO association
(associationID, callingAgent, calledAgent, callingAET, calledAET,
originationTimestamp, confirmationTimestamp, coreConfirmationTimestamp,
numberOfInstancesSent, numberOfInstancesReceived,
coreNumberOfInstancesReceived, status, complete, request) VALUES ($1, $2,
$3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14)]
[9191---2006-10-11 02:32:13.187 EDT]LOG: received immediate shutdown
request
[9913-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]WARNING: terminating
connection because of crash of another server process
[9913-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]DETAIL: The postmaster has
commanded this server process to roll back the current transaction and exit,
because another server process exited abnormally and possibly corrupted
shared memory.
[9913-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]HINT: In a moment you
should be able to reconnect to the database and repeat your command.
[9913-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]STATEMENT: INSERT INTO
JMS_MESSAGES (MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP)
VALUES($1,$2,$3,$4,$5)
[9944-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]WARNING: terminating
connection because of crash of another server process
[9944-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]DETAIL: The postmaster has
commanded this server process to roll back the current transaction and exit,
because another server process exited abnormally and possibly corrupted
shared memory.
[9944-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]HINT: In a moment you
should be able to reconnect to the database and repeat your command.
[9944-jbossdb-jboss-2006-10-11 02:32:13.189 EDT]STATEMENT: INSERT INTO
JMS_MESSAGES (MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP)
VALUES($1,$2,$3,$4,$5)
[9928---2006-10-11 02:32:13.195 EDT]WARNING: terminating connection because
of crash of another server process
[9928---2006-10-11 02:32:13.195 EDT]DETAIL: The postmaster has commanded
this server process to roll back the current transaction and exit, because
another server process exited abnormally and possibly corrupted shared
memory.
[9928---2006-10-11 02:32:13.195 EDT]HINT: In a moment you should be able to
reconnect to the database and repeat your command.
[9193---2006-10-11 02:32:13.414 EDT]LOG: logger shutting down

At time of problem:

[postgres]# ps -ef | grep postg
postgres 9191 1 0 Oct10 ? 00:00:00 /usr/bin/postmaster -p 5432
-D /pgdata/data
postgres 9193 9191 0 Oct10 ? 00:00:00 postgres: logger process
postgres 9195 9191 0 Oct10 ? 00:00:28 postgres: writer process
postgres 9196 9191 0 Oct10 ? 00:01:28 postgres: stats buffer
process
postgres 9198 9196 0 Oct10 ? 00:01:14 postgres: stats collector
process
postgres 9913 9191 0 00:05 ? 00:00:04 postgres: jboss jbossdb
172.16.9.10(36308) INSERT waiting
postgres 9928 9191 2 00:17 ? 00:03:37 postgres: autovacuum process
jbossdb
postgres 9943 9191 0 00:58 ? 00:00:00 postgres: jboss jbossdb
172.16.9.10(36314) idle
postgres 9944 9191 0 00:58 ? 00:00:00 postgres: jboss jbossdb
172.16.9.10(36315) INSERT waiting