Thread: BUG #3032: Commit hung for days

BUG #3032: Commit hung for days

From

"Craig White"

Date:

22 February 2007, 21:39:20

The following bug has been logged online:

Bug reference:      3032
Logged by:          Craig White
Email address:      craig@digital-rapids.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)

Re: BUG #3032: Commit hung for days

From

Magnus Hagander

Date:

23 February 2007, 07:29:28

Craig White wrote:
> The following bug has been logged online:
>
> Bug reference:      3032
> Logged by:          Craig White
> Email address:      craig@digital-rapids.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:

The interesting thing would be to see the server logs, not the
application logs. Specifically, an issue that could look just like this
was fixed in 8.1.7, in which case you would see weird error messages
about permission denied or such in the *server* logs. None of that would
show up in the client logs.

So I would suggest upgrading to the latest release in 8.1.x.

//Magnus

Re: BUG #3032: Commit hung for days

From

"Craig White"

Date:

25 February 2007, 16:11:45

Thanks for the response Magnus.  The server logs do not show anything
unusual, other than the occurrence 5 minutes prior.  I will still take
your advice on the upgrade.

2007-02-15 19:54:13 LOG:  autovacuum: processing database "MM"
2007-02-15 19:55:13 LOG:  autovacuum: processing database "postgres"
2007-02-15 19:55:37 ERROR:  could not read block 558 of relation
1663/16403/16599: Invalid argument
2007-02-15 19:55:37 ERROR:  current transaction is aborted, commands
ignored until end of transaction block
2007-02-15 19:56:38 LOG:  autovacuum: processing database "MM"
2007-02-15 19:57:38 LOG:  autovacuum: processing database "postgres"
2007-02-15 19:58:38 LOG:  autovacuum: processing database "MM"
2007-02-15 19:59:38 LOG:  autovacuum: processing database "postgres"
2007-02-15 20:00:38 LOG:  autovacuum: processing database "MM"
2007-02-15 20:01:38 LOG:  autovacuum: processing database "postgres"
2007-02-15 20:02:38 LOG:  autovacuum: processing database "MM"
2007-02-15 20:03:38 LOG:  autovacuum: processing database "postgres"
2007-02-15 20:04:38 LOG:  autovacuum: processing database "MM"
.....


> -----Original Message-----
> From: Magnus Hagander [mailto:magnus@hagander.net]
> Sent: Friday, February 23, 2007 3:29 AM
> To: Craig White
> Cc: pgsql-bugs@postgresql.org
> Subject: Re: [BUGS] BUG #3032: Commit hung for days
>=20
> Craig White wrote:
> > The following bug has been logged online:
> >
> > Bug reference:      3032
> > Logged by:          Craig White
> > Email address:      craig@digital-rapids.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:
>=20
> The interesting thing would be to see the server logs, not the
> application logs. Specifically, an issue that could look just like
this
> was fixed in 8.1.7, in which case you would see weird error messages
> about permission denied or such in the *server* logs. None of that
would
> show up in the client logs.
>=20
> So I would suggest upgrading to the latest release in 8.1.x.
>=20
> //Magnus