BUG #3032: Commit hung for days

The following bug has been logged online:

Bug reference: 3032
Logged by: Craig White
Email address: craig(at)digital-rapids(dot)com
PostgreSQL version: 8.1.5
Operating system: Windows XP
Description: Commit hung for days
Details:

I'm not looking for quick answers or a fix, but I wanted to submit this for
your information.

Setup:

Java App using Hibernate 3.2.1, C3P0 connection pool, JDBC to PostgreSQL
database.

PostgreSQL setup is pretty much the defaults.

Occurrence:

During some load testing of my application (best characterized as a
multi-threaded transaction processing system), I ran into a transaction that
appeared to get stuck in its Commit. Using pgAdminIII, the 'Server Status'
window shows the Commit Query from 4 days prior. Other connections
periodically execute a statement quickly and successfully so there are not 2
statements in deadlock.

The commit would have been altering a small number of rows from a couple
tables.

The commit happened at 2007/02/15 20:02:10, the only odd occurrence in my
logs occurred 5 minutes earlier. I'm not sure if it is releated or not.
There was a lot of successful activity between 19:57 and 20:02. I'm not yet
sure of the cause of this error, but the prior error log is as follows:

INFO | jvm 1 | 2007/02/15 19:57:39 | 2007-02-15 19:57:39.949 WARN
[T:ServerTranscodeTaskMgr_BG-3][JDBCExceptionReporter] SQL Error: 0,
SQLState: XX000
INFO | jvm 1 | 2007/02/15 19:57:39 | 2007-02-15 19:57:39.949 ERROR
[T:ServerTranscodeTaskMgr_BG-3][JDBCExceptionReporter] ERROR: could not read
block 558 of relation 1663/16403/16599: Invalid argument
INFO | jvm 1 | 2007/02/15 19:57:39 | 2007-02-15 19:57:39.949 ERROR
[T:ServerTranscodeTaskMgr_BG-3][AbstractFlushingEventListener] Could not
synchronize database state with session
INFO | jvm 1 | 2007/02/15 19:57:39 |
org.hibernate.exception.GenericJDBCException: could not insert collection
rows:
[ca.digitalrapids.mediamanager.common.model.TranscodeTaskBean.jobs#3fb70ecf-
0e60-4fe3-8991-2cb37b640640]
INFO | jvm 1 | 2007/02/15 19:57:39 | at
org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLSta
teConverter.java:103)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)

INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java
:43)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(Ab
stractCollectionPersister.java:1394)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.action.CollectionUpdateAction.execute(CollectionUpdateAction.j
ava:56)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:232)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:142)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(Abst
ractFlushingEventListener.java:298)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventL
istener.java:27)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.persist.hibernate.HibernateUtil.commitTransaction(Hibernate
Util.java:329)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr.attemptTranscode
sWithAlg(ServerTranscodeTaskMgr.java:408)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr.checkGroupForWor
k(ServerTranscodeTaskMgr.java:226)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr$3.run(ServerTran
scodeTaskMgr.java:185)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.FutureTask.run(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$
301(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unk
nown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at java.lang.Thread.run(Unknown
Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | Caused by:
org.postgresql.util.PSQLException: ERROR: could not read block 558 of
relation 1663/16403/16599: Invalid argument
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorI
mpl.java:1512)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.ja
va:1297)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:188)

INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.j
ava:437)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2St
atement.java:353)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2State
ment.java:307)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPre
paredStatement.java:105)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:23)

INFO | jvm 1 | 2007/02/15 19:57:40 | at
org.hibernate.persister.collection.AbstractCollectionPersister.insertRows(Ab
stractCollectionPersister.java:1367)
INFO | jvm 1 | 2007/02/15 19:57:40 | ... 21 more
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 SEVERE
HibernateUtil [ServerTranscodeTaskMgr_BG-3]:
org.hibernate.exception.GenericJDBCException: could not insert collection
rows:
[ca.digitalrapids.mediamanager.common.model.TranscodeTaskBean.jobs#3fb70ecf-
0e60-4fe3-8991-2cb37b640640]
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 INFO
ServerMessageCenter [ServerMessageCenter_LBG-1]: Alert is spamming: Job is
Running (DRC-1RU-03 S/W)
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 INFO HibernateUtil
[ServerTranscodeTaskMgr_BG-3]: Trying to rollback database transaction of
this thread.
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 INFO HibernateUtil
[ServerTranscodeTaskMgr_BG-3]: Database transaction rolled back.
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 WARNING
HibernateUtil [ServerTranscodeTaskMgr_BG-3]: closeSession called, but not
open for this thread
INFO | jvm 1 | 2007/02/15 19:57:40 | 02-15 19:57:39 WARNING
HibernateUtil [ServerTranscodeTaskMgr_BG-3]: closeSession called, but not
open for this thread
INFO | jvm 1 | 2007/02/15 19:57:40 | java.lang.IllegalStateException:
Rollback Transaction called with none in progress
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.persist.hibernate.HibernateUtil.rollbackTransaction(Hiberna
teUtil.java:363)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr.attemptTranscode
sWithAlg(ServerTranscodeTaskMgr.java:415)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr.checkGroupForWor
k(ServerTranscodeTaskMgr.java:226)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
ca.digitalrapids.mediamanager.server.ServerTranscodeTaskMgr$3.run(ServerTran
scodeTaskMgr.java:185)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.FutureTask.run(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$
301(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unk
nown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at
java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO | jvm 1 | 2007/02/15 19:57:40 | at java.lang.Thread.run(Unknown
Source)