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

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
>