asked on

c3p0 lock-up

hello, we just started our production setup with real beta user traffic, and i'm facing regular (1-2 times a day) lock-ups of c3p0, with stack traces like these:

the hibernate.cfg.xml snippet for c3p0

<property name="hibernate.c3p0.min_size">5</property>
<property name="hibernate.c3p0.max_size">20</property>
<property name="hibernate.c3p0.acquire_increment">2</property>
<property name="hibernate.c3p0.max_statements">0</property>
<property name="hibernate.c3p0.timeout">25200</property>
<property name="hibernate.c3p0.idle_test_period">14400</property>
<property name="hibernate.c3p0.preferredTestQuery">select 1;</property>

(there is no c3p0.properties file)

Hibernate version:
3.3.1

c3p0 version:
0.9.1.2

Name and version of the database you are using:
mySQL 5.0.45

i'm trying to reproduce this on our dev-system, but so far no luck.

i'm not sure i understand whats going on - the max number of connections does not seem to be reached.

side note - because of an apparent class loader problem (that i'm working on), i'm having 2 HibernateUtil singleton instances in 2 parts of the system, instead of one. the problem always appears in the same one.

side question - i'm currently using openSession, (how) would getCurrentSession make a difference?

any hint is greatly appreciated!

best,
thomas

INFO   | jvm 1    | 2009/02/22 20:40:49 | "pool-11-thread-1" prio=10 tid=0x094d2c00 nid=0x212 in Object.wait() [0xaeed1000..0xaeed1db0]
INFO   | jvm 1    | 2009/02/22 20:40:49 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- waiting on <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- locked <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.SessionUtil.updateSessionLifetime(SessionUtil.java:117)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.SessionLifetimeTaskHandler.doTask(SessionLifetimeTaskHandler.java:32)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at it.gotoandplay.smartfoxserver.util.scheduling.Scheduler.executeTasks(Scheduler.java:305)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- locked <0xb92c3fc8> (a java.util.LinkedList)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at it.gotoandplay.smartfoxserver.util.scheduling.Scheduler.run(Scheduler.java:223)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at java.lang.Thread.run(Unknown Source)
 
INFO   | jvm 1    | 2009/02/22 20:40:49 | "btpool0-8" prio=10 tid=0x08d95400 nid=0x1bc in Object.wait() [0xafcaa000..0xafcaaf30]
INFO   | jvm 1    | 2009/02/22 20:40:49 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       - waiting on <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)   
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- locked <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1560)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.doQuery(Loader.java:661)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doList(Loader.java:2144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2028)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.list(Loader.java:2023)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:393)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:780)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.BuddyHelper.isAnyBuddyOnline(BuddyHelper.java:87)
 
INFO   | jvm 1    | 2009/02/22 20:40:49 | "btpool0-5" prio=10 tid=0x08d9b800 nid=0x1b9 in Object.wait() [0xafd9d000..0xafd9ddb0]
INFO   | jvm 1    | 2009/02/22 20:40:49 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       - waiting on <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)   
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- locked <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1560)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.doQuery(Loader.java:661)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doList(Loader.java:2144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2028)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.list(Loader.java:2023)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:393)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:780)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.BuddyHelper.isAnyBuddyOnline(BuddyHelper.java:87)
 
INFO   | jvm 1    | 2009/02/22 20:40:49 | "btpool0-4" prio=10 tid=0x08d9ac00 nid=0x1b8 in Object.wait() [0xafdee000..0xafdef130]
INFO   | jvm 1    | 2009/02/22 20:40:49 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       - waiting on <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       - locked <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1560)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.doQuery(Loader.java:661)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.doList(Loader.java:2144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2028)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.list(Loader.java:2023)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:393)
 
INFO   | jvm 1    | 2009/02/22 20:40:49 | "btpool0-0" prio=10 tid=0x08e4fc00 nid=0x1b4 in Object.wait() [0xb00c9000..0xb00c9f30]
INFO   | jvm 1    | 2009/02/22 20:40:49 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- waiting on <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	- locked <0xb90acc20> (a com.mchange.v2.resourcepool.BasicResourcePool)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1560)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doQuery(Loader.java:661)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.loader.Loader.doList(Loader.java:2144)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2028)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.Loader.list(Loader.java:2023)
INFO   | jvm 1    | 2009/02/22 20:40:49 |       at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:393)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:780)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.BuddyHelper.isAnyBuddyOnline(BuddyHelper.java:87)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at my.InfoServlet.doGet(InfoServlet.java:75)
INFO   | jvm 1    | 2009/02/22 20:40:49 |	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)

Open in new window

ASKER CERTIFIED SOLUTION

Ajay-Singh

membership

This solution is only available to members.

To access this solution, you must be a member of Experts Exchange.

Start Free Trial

thomers1

ASKER

i have enabled statistics to show me opened and closed connections (using sessionFactory.getStatistics().getSessionOpenCount() and sessionFactory.getStatistics().getSessionCloseCount() ) on every DB action. the numbers are the same, so i assume i release everything.

i don't make use of c3p0 directly, but just configured it as connection pool for hibernate to use.

thomers1

ASKER

hang on, apparently, i was viewing the statistics of the wrong singleton... will update.

thomers1

ASKER

stupid me - thanks