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:
Code:
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)
the hibernate.cfg.xml snippet for c3p0
Code:
<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