Re: "Hanging Connection" blocks access to table (JBossMQ)

I shut down postgresql manually (pg_ctl restart -m immediiate) after I had
first stopped Jboss and waited about 30 seconds to see that the two blocking
connections were not closing.

Jboss should terminate the query with either a commit or a rollback.

Mike

On 10/11/06 1:57 PM, "Dave Cramer" <pg(at)fastcrypt(dot)com> wrote:

> Michael,
>
> who issued the shutdown of postgresql ? Did you do this manually ?
>
> Also how does JBoss "terminate the query" ?
>
> Dave
> On 11-Oct-06, at 1:14 PM, Michael Goldner wrote:
>
>> 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
>>
>>
>>
>> ---------------------------(end of
>> broadcast)---------------------------
>> TIP 6: explain analyze is your friend
>>
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

--
Mike Goldner
Vice President Networks and Technology
AG Mednet, Inc.
The Pilot House
Lewis Wharf
Boston, MA 02110
617.854.3225 (office)
617.909.3009 (mobile)