Skip site navigation (1) Skip section navigation (2)

BUG #3032: Commit hung for days

From: "Craig White" <craig(at)digital-rapids(dot)com>
To: pgsql-bugs(at)postgresql(dot)org
Subject: BUG #3032: Commit hung for days
Date: 2007-02-19 19:30:00
Message-ID: 200702191930.l1JJU0eW028471@wwwmaster.postgresql.org (view raw or flat)
Thread:
Lists: pgsql-bugs
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)

Responses

pgsql-bugs by date

Next:From: Luigi TarengaDate: 2007-02-19 20:27:32
Subject: BUG #3033: performance issue with self join
Previous:From: Arjen van der MeijdenDate: 2007-02-19 18:52:23
Subject: BUG #3031: PHP (and others?) cannot close a connection when "in" a COPY-statement

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group