c3p0:JDBC DataSources/Resource Pools / Bugs / #136 Threads waiting in BasicResourcePool.awaitAvailable forever

Steve Waldman - 2016-04-04

hi,

threads aren’t locked they are wait()ing. your application very likely has a Connection leak.

please verify that the settings you intend are getting to the pool. as listed, you must have written custom logic to set these parameters, as you show them in properties file format but beginning with capital letters and not prefixed with c3p0, as would be necessary in a standard c3p0.properties file.

c3p0 pools dump their config at INFO on initialization. check your logs to verify (or alternatively you can check via JMX).

to debug Connection leaks, please review
http://www.mchange.com/projects/c3p0/#configuring_to_debug_and_workaround_broken_clients
http://www.mchange.com/projects/c3p0/#unreturnedConnectionTimeout
http://www.mchange.com/projects/c3p0/#debugUnreturnedConnectionStackTraces

basically set config params unreturnedConnectionTimeout and debugUnreturnedConnectionStackTraces simultaneously, and check your logs for codepaths that check out but sometimes fail to return Connections.

in hibernate, be sure that Sessions are always promptly closed after use.

smiles, steve

On Apr 4, 2016, at 3:32 AM, Sergiu Hlihor sergiuhlihor@users.sf.net wrote:

[bugs:#136] Threads waiting in BasicResourcePool.awaitAvailable forever

Status: open
Group: v1.0 (example)
Labels: concurrent access waiting blocked BasicResourcePool
Created: Mon Apr 04, 2016 10:32 AM UTC by Sergiu Hlihor
Last Updated: Mon Apr 04, 2016 10:32 AM UTC
Owner: Steve Waldman

Connection checkout blocks forever in BasicResourcePool.awaitAvailable when concurrent access is used. The threads get locked sometimes right away, sometimes after some time which suggests a concurrency issue. Please check or suggest a fix as this prevents concurrent usage in production.
The settings used are:
IdleConnectionTestPeriod=100
MaxIdleTime=600
MaxConnectionAge=7200
MaxIdleTimeExcessConnections=300
MaxStatements=0
TestConnectionOnCheckout=false
PreferredTestQuery="SELECT 1"
SetNumHelperThreads=10
MinPoolSize=10
MaxPoolSize=200

The max number of threads used at application level is limited to 24 which is way below the MaxPoolSize value. Based on database logs, the connection load was less than 15% at the time of incident.
Belows is a full thread dump of relevant code:
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1465)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644)
- locked <0x00000004dbe035c8> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
at org.hibernate.loader.Loader.doQuery(Loader.java:909)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
at org.hibernate.loader.Loader.doList(Loader.java:2553)
at org.hibernate.loader.Loader.doList(Loader.java:2539)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
at org.hibernate.loader.Loader.list(Loader.java:2364)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573)
at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:449)

Sent from sourceforge.net because you indicated interest in https://sourceforge.net/p/c3p0/bugs/136/

To unsubscribe from further messages, please visit https://sourceforge.net/auth/subscriptions/

Related

Bugs: #136
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sergiu Hlihor - 2016-04-04

All the parameters listed are set programatically to a ComboPooledDataSource instance used to construct pool.

We are observing the issue consistently once every few days in an batch processing tool that we use and that runs every 15 minutes. Technically, even with a connection leak, based on the way it's used, it cannot leak more connections that total number of available ones.

I'll comeback once I'll have more debugging info.

Last edit: Sergiu Hlihor 2016-04-04

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sergiu Hlihor - 2016-04-13

More data: the implementation is actively using up to 24 connections and according to JMX monitoring, the number of connections never peaked above 23 during the last incident. The connection pool is configured to 500 and this value was never reached (crosschecked with maximum database connections during the time).

Please have a look over the configuration parameters (taken from JMX) and advise for any missconfiguration that can lead to threads waiting for connections forever. The batch tool is running on a 2*12 core machine and up to 24 connections are acquired immediately after startup. We are seeing this issue on batch tools which acquire a large number of connections at once.

The issue was observed with both versions 0.9.5.1 and 0.9.5.2

JMX Datasource parameters:

numConnectionsDefaultUser 23
forceSynchronousCheckins false
numFailedCheckoutsDefaultUser 0
usesTraditionalReflectiveProxies false
userOverrides {}
numBusyConnectionsAllUsers 23
statementCacheNumConnectionsWithCachedStatementsDefaultUser 0
statementDestroyerNumConnectionsInUseDefaultUser -1
minPoolSize 5
numBusyConnectionsDefaultUser 23
numConnectionsAllUsers 23
statementDestroyerNumTasksPending -1
loginTimeout 0
statementDestroyerNumConnectionsInUseAllUsers -1
acquireIncrement 3
statementCacheNumCheckedOutDefaultUser 0
statementCacheNumDeferredCloseThreads 0
preferredTestQuery SELECT 1
numFailedIdleTestsDefaultUser 0
checkoutTimeout 0
maxStatements 0
threadPoolSize 10
statementDestroyerNumActiveThreads -1
forceIgnoreUnresolvedTransactions false
statementCacheNumStatementsDefaultUser 0
numIdleConnections 0
unreturnedConnectionTimeout 0
statementDestroyerNumDeferredDestroyStatementsDefaultUser -1
numUnclosedOrphanedConnections 0
maxPoolSize 500
numBusyConnections 23
forceUseNamedDriverClass false
acquireRetryDelay 1000
statementCacheNumConnectionsWithCachedStatementsAllUsers 0
effectivePropertyCycleDefaultUser 75.0
contextClassLoaderSource caller
numIdleConnectionsDefaultUser 0
maxAdministrativeTaskTime 0
testConnectionOnCheckout false
numUserPools 1
numUnclosedOrphanedConnectionsDefaultUser 0
threadPoolNumTasksPending 0
statementCacheNumStatementsAllUsers 0
upTimeMillisDefaultUser 515599100
propertyCycle 0
statementDestroyerNumIdleThreads -1
numHelperThreads 10
idleConnectionTestPeriod 100
debugUnreturnedConnectionStackTraces false
breakAfterAcquireFailure false
statementDestroyerNumDeferredDestroyStatementsAllUsers -1
privilegeSpawnedThreads false
numFailedCheckinsDefaultUser 0
numUnclosedOrphanedConnectionsAllUsers 0
numIdleConnectionsAllUsers 0
numThreadsAwaitingCheckoutDefaultUser 1
maxStatementsPerConnection 0
startTimeMillisDefaultUser 1460030887654
statementDestroyerNumConnectionsWithDeferredDestroyStatementsDefaultUser -1
maxIdleTimeExcessConnections 300
testConnectionOnCheckin false
statementDestroyerNumThreads -1
statementDestroyerNumConnectionsWithDeferredDestroyStatementsAllUsers -1
acquireRetryAttempts 30
threadPoolNumActiveThreads 0
autoCommitOnClose false
jdbcUrl jdbc:mysql://127.0.0.1:3306/xxx?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true
maxConnectionAge 7200
initialPoolSize 3
maxIdleTime 600
statementCacheNumCheckedOutStatementsAllUsers 0
numConnections 23
extensions {}
threadPoolNumIdleThreads 10
connectionTesterClassName com.mchange.v2.c3p0.impl.DefaultConnectionTester

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sergiu Hlihor - 2016-05-19

Update:
The issue is no longer observed for more than one month when decreasing the number of threads below 24. Stacktrace and configuration strongly suggest a bug in connection initialization procedure.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Alexey - 2017-12-28

We faced exactly the same issue and can reproduce it when DB connection pool size < active threads.
For sample connection pool 8 connections and 35 active threads which get connections from the pool. C3P0 pool stuck after 8 connections open (can see them from as connections open from DB side) and after with small delay C3P0 pool stuck and all threads become waiting for the next connection from the pool. Threads that keep connection open can't return it to the pool as pool stuck and other threads can't get connection from the pool.
As workaround we limited count of working threads to match with max connection pool value.

Last edit: Alexey 2017-12-29

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Alexey - 2017-12-29

Added log4jdbc and started to trace when connection open/close. Found that when we use hibernate it manage connection state by himself. Basically it close connection when sessionFactory.close() invoked.
This is a root cause. So it is not a bug in C3P0 connection. Hibernate sessionFactory just didn't return connection to the pool until it closed. In our case it was due to hibernate.connection.release_mode=on_close.
You can configured it behavior via 'hibernate.connection.release_mode'.

Last edit: Alexey 2017-12-29

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Threads waiting in BasicResourcePool.awaitAvailable forever

Group

Searches

Help

#136 Threads waiting in BasicResourcePool.awaitAvailable forever

Related

Discussion

Related