Re: "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

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
>

Michael Goldner <mike(dot)goldner(at)comcast(dot)net> writes:
> Could autovacuum be using enough memory so that postgres cannot handle
> the insert of the large row?

No. You might be having locking problems, though --- have you looked
into pg_locks to see if anything is blocked on a lock? Those "INSERT
waiting" processes certainly look like they are so blocked.

There was a thread just yesterday
http://archives.postgresql.org/pgsql-performance/2006-10/msg00190.php
suggesting that 8.1's autovacuum might have some as-yet-undetermined
locking issues, but that's only speculation at this point. If you can
get some evidence showing that it's really happening, I'm all ears...

regards, tom lane

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)

Michael Goldner <mgoldner(at)agmednet(dot)com> writes:
> 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.

Really? "-m immediate" should boot backends off lock waits in any case
... and does according to my tests. Whether Jboss notices the
connections dropping right away might be another story. What are you
observing as a "not closed" connection?

I wouldn't personally use "-m immediate" for this purpose mind you.
"-m fast" is safer and should have the same result.

regards, tom lane

I should have worded my response more carefully ;)

With both Jboss and Postgresql running, a "ps -ef |grep postgres" shows two
processes in an "INSERT waiting" state, one in an idle state and the
autovacuum process.

Jboss is the only application that uses the database, so I'm sure that the
processes are not for something else.

When I shutdown Jboss, the idle process disappears, but the 2 "INSERT
waiting" processes remain indefinitely. Once I restart Postgres, everything
immediately clears and it starts again in a normal state with no blocking.

I'm going to see if I can put together a test environment to reproduce the
problem, but simulating load conditions is always tricky. If I can produce
it, I'll be able to gather more information (strace, gdb, etc.).

Thanks,

Mike

On 10/11/06 2:57 PM, "Tom Lane" <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Michael Goldner <mgoldner(at)agmednet(dot)com> writes:
>> 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.
>
> Really? "-m immediate" should boot backends off lock waits in any case
> ... and does according to my tests. Whether Jboss notices the
> connections dropping right away might be another story. What are you
> observing as a "not closed" connection?
>
> I wouldn't personally use "-m immediate" for this purpose mind you.
> "-m fast" is safer and should have the same result.
>
> regards, tom lane

--
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)

Michael Goldner <mgoldner(at)agmednet(dot)com> writes:
> When I shutdown Jboss, the idle process disappears, but the 2 "INSERT
> waiting" processes remain indefinitely.

Ah. That makes sense, because a backend blocked partway through a query
isn't going to notice its client disconnecting. The question here
though is still "what are they waiting for?". See pg_locks.

regards, tom lane

Hi, Tom,

Tom Lane wrote:
> Michael Goldner <mgoldner(at)agmednet(dot)com> writes:
>> When I shutdown Jboss, the idle process disappears, but the 2 "INSERT
>> waiting" processes remain indefinitely.
>
> Ah. That makes sense, because a backend blocked partway through a query
> isn't going to notice its client disconnecting. The question here
> though is still "what are they waiting for?". See pg_locks.

Is there any possibility that we make a backend realize this SIGIO (or
whatever it gets) when the connection is closed? I often had the problem
that I shut down my application, but the server kept working on that
query for a long time.

The same is for very long running C-Code functions (like PostGIS
geomUnion() on geometries with millions of vertices), those also tend to
block the backend for long times, without any possibility to kill it
except SIGKILL.

Thanks,
Markus
--
Markus Schaber | Logical Tracking&Tracing International AG
Dipl. Inf. | Software Development GIS

Fight against software patents in Europe! www.ffii.org
www.nosoftwarepatents.org

Markus Schaber <schabi(at)logix-tt(dot)com> writes:
> Is there any possibility that we make a backend realize this SIGIO (or
> whatever it gets) when the connection is closed?

I don't think it'd be a net win to add cycles to every query to check
the connection every so often.

> The same is for very long running C-Code functions (like PostGIS
> geomUnion() on geometries with millions of vertices), those also tend to
> block the backend for long times, without any possibility to kill it
> except SIGKILL.

That's the fault of the C code ... it should be doing
CHECK_FOR_INTERRUPTS periodically in any long-running loops.

regards, tom lane

Hi, Tom,

Tom Lane wrote:
>> Is there any possibility that we make a backend realize this SIGIO (or
>> whatever it gets) when the connection is closed?
> I don't think it'd be a net win to add cycles to every query to check
> the connection every so often.

The SIGIO could set a flag variable via the interrupt handler, and then
the backend could check that variable in a few, selected places. This
should keep the overhead pretty low. And when the connection is low,
there really is no point in continuing to work on the current query.

>> The same is for very long running C-Code functions (like PostGIS
>> geomUnion() on geometries with millions of vertices), those also tend to
>> block the backend for long times, without any possibility to kill it
>> except SIGKILL.
>
> That's the fault of the C code ... it should be doing
> CHECK_FOR_INTERRUPTS periodically in any long-running loops.

The problem is that most of those long-running functions are in
3rd-party libs like GEOS and ProJ, which are basically only wrapped by
PostGIS, so it won't be easy to sprinkle them with CHECK_FOR_INTERRUPTS.

I suspect that plR might suffer from the same problem.

So we'll have to live with this.

Thanks,
Markus
--
Markus Schaber | Logical Tracking&Tracing International AG
Dipl. Inf. | Software Development GIS

Fight against software patents in Europe! www.ffii.org
www.nosoftwarepatents.org

Markus Schaber <schabi(at)logix-tt(dot)com> writes:
> Tom Lane wrote:
>> I don't think it'd be a net win to add cycles to every query to check
>> the connection every so often.

> The SIGIO could set a flag variable via the interrupt handler,

SIGIO isn't portable (nowhere to be seen in Single Unix Spec), and where
it does exist, it seems to report I/O ready on *any* descriptor not only
the one you want. That would lead to a whole lot of useless interrupts
and status-checks.

regards, tom lane