-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 4 posts ] 
  Previous topic | Next topic 
Author Message
gentlehardcore
 Post subject: c3p0 - APPARENT DEADLOCK errors
PostPosted: Mon May 26, 2008 4:00 pm 
Newbie

Joined: Thu Jun 14, 2007 4:19 pm
Posts: 6
Hello

Hibernate version:
3.2.6 GA

Mapping documents:
Code:
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE hibernate-configuration PUBLIC
"-//Hibernate/Hibernate Configuration DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
   <session-factory>
      <property name="hibernate.bytecode.use_reflection_optimizer">false</property>
      <property name="hibernate.connection.driver_class">oracle.jdbc.OracleDriver</property>

      <property name="hibernate.connection.url">jdbc:oracle:thin:@chmiel.somwhere.com:1521:mz?database</property>
      <property name="hibernate.connection.username">***</property>
      <property name="hibernate.connection.password">***</property>
      <property name="hibernate.connection.autocommit">false</property>
      

      <property name="hibernate.current_session_context_class">thread</property>
      <!-- Oracle9Dialect is deprecated. See Oracle9Dialect.java Hibernate core source code. -->
      <property name="hibernate.dialect">org.hibernate.dialect.Oracle9iDialect</property>
      
      <property name="cache.provider_class">org.hibernate.cache.NoCacheProvider</property>


      <property name="hibernate.format_sql">true</property>
      <property name="hibernate.show_sql">true</property>
      <property name="hibernate.use_sql_comments">true</property>

      <property name="hibernate.jdbc.fetch_size">101</property>
      <property name="hibernate.jdbc.batch_size">102</property>
      <property name="hibernate.default_batch_fetch_size">103</property>

      <property name="connection.provider_class">org.hibernate.connection.C3P0ConnectionProvider</property>

      <property name="hibernate.c3p0.acquire_increment">1</property>
      <property name="hibernate.c3p0.idle_test_period">0</property>
      <property name="hibernate.c3p0.min_size">0</property>
      <property name="hibernate.c3p0.max_size">48</property>
      <property name="hibernate.c3p0.max_statements">250</property>
      <property name="hibernate.c3p0.timeout">0</property>
   </session-factory>
</hibernate-configuration>


Name and version of the database you are using:
Oracle 9

JDBC version:
The latest Oracle JDBC Driver (11g Release 1 (11.1.0.6) drivers).
I choose JDBC driver for Java 6.

c3p0 version:
The latest available on the Internet: c3p0-0.9.1.2.
I overwrote c3p0 jar file attached to Hibernate Core library.

c3p0.properties config file:
Code:
c3p0.acquireRetryAttempts=2
c3p0.acquireRetryDelay=2500
c3p0.numHelperThreads=10


Java version:
The latest Sun Java 6 version (Windows 2003 platform, 32 bit).

I've got (well known) problem with c3p0 and "APPARENT DEADLOCK!!!" errors.

My application is a standalone app. It is multithreaded app procesing thousand of database transactions in every working thread. There are about 16 worker threads.

But after several database transactions I've got a "APPARENT DEADLOCK!!!" errors in my log4j logfile:

Code:
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.loader.Loader - processing result set
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.loader.Loader - result set row: 0
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.loader.Loader - result row:
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.type.NullableType - returning '0' as column: col_0_0_
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.loader.Loader - done processing result set (1 rows)
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 13)
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.jdbc.AbstractBatcher - closing statement
2008-05-26 17:14:01,134 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 28; num connections: 17; num keys: 234
2008-05-26 17:14:01,134 [  11] DEBUG (484) org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
2008-05-26 17:14:01,134 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
2008-05-26 17:14:01,134 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 29; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  10] DEBUG (495) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 28; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  10] DEBUG (495) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 27; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  10] DEBUG (495) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 26; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 25; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 24; num connections: 17; num keys: 234
2008-05-26 17:14:01,150 [  11] DEBUG (484) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 23; num connections: 17; num keys: 234
2008-05-26 17:14:11,822 [Timer-0] WARN  () com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@1bda414 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
2008-05-26 17:14:11,838 [Timer-0] WARN  () com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector - com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@1bda414 -- APPARENT DEADLOCK!!! Complete Status:
   Managed Threads: 10
   Active Threads: 10
   Active Tasks:
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1565730 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1763f29 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@2c9d7e (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#8)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@117f9dc (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@114de27 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#9)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@104eeb1 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@d2c4bc (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@17233e3 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@aca3ce (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@362bc7 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3)
   Pending Tasks:
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@744830
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@2f719a
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@cb5e96
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@1aef86b
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask@3768da
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1c4c573
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@17f1fac
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@f89071
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@d2fa99
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1427c43
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1ec394e
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1a66e6b
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@19b34ac
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@9f1a77
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@1828c62
Pool thread stack traces:
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#8,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#9,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
   Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3,5,main]
      oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1445)
      oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:75)
      oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:77)
      com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:41)
      com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StatementCloseTask.run(GooGooStatementCache.java:404)
      com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)


2008-05-26 17:14:11,838 [Timer-0] DEBUG () com.mchange.v2.async.ThreadPoolAsynchronousRunner - Apparently some threads have been replaced. Replacement thread processing enabled.
2008-05-26 17:14:11,900 [  12] DEBUG (503) com.mchange.v2.c3p0.stmt.GooGooStatementCache$Deathmarch - CULLING: { call TAROPTSTUBPKG.process_takeover_stub(?,?,?,?,?)}
2008-05-26 17:14:11,900 [  12] DEBUG (503) com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( oracle.jdbc.driver.T4CConnection@1da02d7 ).size(): 15
2008-05-26 17:14:11,900 [  12] DEBUG (503) com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 250; checked out: 24; num connections: 17; num keys: 234


I am struggling with it since last week I would be appreciated if somebody has an idea what is the reason of those deadlock.

I can provide other pieces of my logfile.

Kind regards,
Adaslaw
Top
 Profile  
 
gentlehardcore
 Post subject:
PostPosted: Wed May 28, 2008 4:18 pm 
Newbie

Joined: Thu Jun 14, 2007 4:19 pm
Posts: 6
Hello

After many, many hours (days actually) I gave up.

I tried to:
* manipulate Oracle JDBC driver versions
* manipulate Hibernate c3p0 related options
* pure c3p0.properties options

... and my multithreaded application still gets APPARENT DEADLOCK when c3p0.maxStatements (or corresponding hibernate.c3p0.max_statements) was greater than 0.

My workaround:
In hibernate.cfg.xml:
Code:
<property name="hibernate.c3p0.max_statements">0</property>


In c3p0.properties:
Code:
c3p0.maxStatements=0
c3p0.maxStatementsPerConnection=100


For such setting my multithreaded applications runs with no APPARENT DEADLOCK error (finally and ... hopefully that this problem is really solved).

My app running quite fast so I guess (and I believe) that Statement caching is working. Statements caching is crucial for me because of performance. In other words I couldn't just turn Statement caching off (*).

As far as I can see turning Statement caching off (this global statement caching) is one (or maybe the only one) solution to get rid of APPARENT DEADLOCK errors.

Damn, I really would like to have time to have a look at c3p0 source code and figure out where is the reason of those fu!@#$% errors (Oracle JDBC or Hibernate or c3p0).

Kind regards,
Adam
Top
 Profile  
 
notorand
 Post subject:
PostPosted: Mon Jul 21, 2008 4:07 am 
Newbie

Joined: Mon Jul 21, 2008 3:42 am
Posts: 2
See my post here
http://forum.hibernate.org/viewtopic.ph ... 09#2390809
Top
 Profile  
 
anuraganuj
 Post subject: statement caching is disabled but see some statement caching
PostPosted: Mon Nov 10, 2008 3:06 am 
Newbie

Joined: Mon Nov 10, 2008 3:00 am
Posts: 1
Location: Gurgaon
I have both

c3p0.maxStatements=0
c3p0.maxStatementsPerConnection=0

I dont see any APPARENT DEADLOCK now in applications logs but i still see following type of messages repeatedly. Could anybody tel what is this due to ?

at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:10656)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)

_________________
Anurag aggarwal
India

Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 4 posts ] 

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.