CODEWITHSUNDEEP
mysqlhibernatec3p0
RobinHood
RobinHood

Reputation: 33

C3PO: A client timed out while waiting to acquire a resource

Current setup:

Service host (Java) connects to (JDBC) Primary DB (MySQL RW) and has a worker (read-only) for reliability. Connection management is handled by C3PO

Scenario:

In case of flip, I need to promote one of worker to primary DB. Present primary becomes read-only and new primary is promoted to read-write. I am looking to reliably, automatically refresh the C3P0 connection pool to the new primary db. Which kind of works now but is broken for certain cases.

Technical: Service has a db host as cname, which would be updated on flip. Before the DNS changes propagate and new db is RW, all connections would fail. Trying to set the C3PO retry infinetly on the connection pool until a connection is RW through (acquireRetryAttempts)

Existing C3PO configuration:

Generic configuration, inherited by primary and worker DB
    <property name="maxIdleTime" value="44000"/>
    <property name="idleConnectionTestPeriod" value="30"/>
    <property name="maxStatements" value="50"/>
    <property name="minPoolSize" value="3"/>
    <property name="maxPoolSize" value="3"/>
    <property name="acquireIncrement" value="2"/>
    <property name="checkoutTimeout" value="15000"/>
    <property name="acquireRetryDelay" value="1000"/>

Primary DB specific config
    <property name="acquireRetryAttempts" value="0"/>
    <property name="minPoolSize" value="3"/>
    <property name="maxPoolSize" value="5"/>
    <property name="testConnectionOnCheckout" value="true"/>
    <property name="connectionTesterClassName" value="${Custom.connectionTesterClassName}"/>

Issue:

Custom connection tester checks if the connection is writable (@@global.read_only) and return connection invalid or valid. The C3PO runs into issue where it would refurbish (kill and reinitialize) the connection pool as stated in intermediate logs. Eventually it checks out all (max_pool_size, 5) connections (in 4-5 min) and hangs in a state where connections don't checkin back to the pool. This causes all subsequent DB connection checkout to timeout and fail as stated in final logs. Forcing to restart services so it would reinitialize C3PO pool.

Ideally I need the connection pool to keep killing and reinitializing if the connectionTesterClassName returns false or on idleConnectionTestPeriod or at some random period. Since the connections are checked out they do not fall under idle connections and aren't refreshed.

Tried to debug using unreturnedConnectionTimeout and debugUnreturnedConnectionStackTraces as stated in C3PO documentation however, no luck.

Logs:

Intermediate logs

com.mchange.v2.resourcepool.BasicResourcePool: Resource [com.mchange.v2.c3p0.impl.NewPooledConnection@24e7ebec] could not be refurbished in preparation for checkout. Will try to find a better resource.
    (C3P0PooledConnectionPoolManager[identityToken->2tyqoiac1gfqk68krloa8|7e2c64]-HelperThread-#6) com.mchange.v2.resourcepool.BasicResourcePool: Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@24e7ebec
23 Sep 2020 22:06:23,780 [DEBUG]com.mchange.v2.resourcepool.BasicResourcePool: acquire test -- pool size: 0; target_pool_size: 3; desired target? 1
23 Sep 2020 22:06:23,780 [DEBUG]  com.mchange.v2.resourcepool.BasicResourcePool: awaitAvailable(): com.mchange.v2.c3p0.impl.NewPooledConnection@4b52cf0c
23 Sep 2020 22:06:23,780 [DEBUG]  (C3P0PooledConnectionPoolManager[identityToken->2tyqoiac1gfqk68krloa8|7e2c64]-HelperThread-#6) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool: Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@24e7ebec
23 Sep 2020 22:06:23,780 [DEBUG]  (C3P0PooledConnectionPoolManager[identityToken->2tyqoiac1gfqk68krloa8|7e2c64]-HelperThread-#6) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool: Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@24e7ebec
23 Sep 2020 22:06:23,780 [DEBUG]  (C3P0PooledConnectionPoolManager[identityToken->2tyqoiac1gfqk68krloa8|7e2c64]-HelperThread-#6) com.mchange.v2.resourcepool.BasicResourcePool: Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@24e7ebec
23 Sep 2020 22:06:23,781 [DEBUG]  com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool: Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@7fff041e] on CHECKOUT.
23 Sep 2020 22:06:23,782 [INFO]  ReadWriteConnectionTester: Connection com.mchange.v2.c3p0.impl.NewProxyConnection@21eb35f6 [wrapping: com.mysql.jdbc.JDBC4Connection@44732406] is read only!
23 Sep 2020 22:06:23,782 [DEBUG]  com.mchange.v2.c3p0.impl.NewProxyConnection: com.mchange.v2.c3p0.impl.NewProxyConnection@21eb35f6 [wrapping: null]: close() called more than once.
23 Sep 2020 22:06:23,782 [DEBUG]  com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool: Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@7fff041e] on CHECKOUT has FAILED.
java.sql.SQLException: Connection is invalid

Final logs:

org.hibernate.engine.jdbc.internal.LogicalConnectionImpl: Obtaining JDBC connection
com.mchange.v2.resourcepool.BasicResourcePool: acquire test -- pool is already maxed out. [managed: 5; max: 5]
com.mchange.v2.resourcepool.BasicResourcePool: awaitAvailable(): com.mchange.v2.c3p0.impl.NewPooledConnection@4b52cf0c

com.mchange.v2.sql.SqlUtils: Converting Throwable to SQLException...
com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@43aeb5e0 -- timeout at awaitAvailable()
    at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1467) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) ~[c3p0-0.9.5.1.jar:0.9.5.1]

org.hibernate.engine.jdbc.spi.SqlExceptionHelper: Could not open connection [n/a]
java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.
    at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:118) ~[mchange-commons-java-0.2.10.jar:0.2.10]
    at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:77) ~[mchange-commons-java-0.2.10.jar:0.2.10]
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:690) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at org.springframework.jdbc.datasource.lookup.AbstractRoutingDataSource.getConnection(AbstractRoutingDataSource.java:164) ~[spring-jdbc-4.3.24.RELEASE.jar:4.3.24.RELEASE]
    at org.hibernate.service.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:141) ~[hibernate-core-4.2.2.Final.jar:4.2.2.Final]
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292) ~[hibernate-core-4.2.2.Final.jar:4.2.2.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214) ~[hibernate-core-4.2.2.Final.jar:4.2.2.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:157) ~[hibernate-core-4.2.2.Final.jar:4.2.2.Final]
    at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:550) ~[hibernate-core-4.2.2.Final.jar:4.2.2.Final]

Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@43aeb5e0 -- timeout at awaitAvailable()
    at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1467) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685) ~[c3p0-0.9.5.1.jar:0.9.5.1]
    ... 51 more

org.hibernate.engine.jdbc.spi.SqlExceptionHelper: SQL Error: 0, SQLState: null
org.hibernate.engine.jdbc.spi.SqlExceptionHelper: An attempt by a client to checkout a Connection has timed out

Upvotes: 0

Views: 2279

Answers (1)

Steve Waldman
Steve Waldman

Reputation: 14083

So, this isn't the right interpretation "refurbish (kill and reinitialize) the connection pool".

It's an individual Connection that the pool is trying to "refurbish" here. It's trying to freshen the Connection up to be ready for use by the client. Since you have testConnectionOnCheckout set to true, and the DB has "flipped", your ReadWriteConnectionTester will declare every Connection in the current pool invalid (because read-only) until the pool runs out of Connections to try or runs out of time due to client timeout.

Does your ReadWriteConnectionTester return ConnectionTester.CONNECTION_IS_INVALID or ConnectionTester.DATABASE_IS_INVALID when it finds a Connection is invalid? You should want it to return ConnectionTester.DATABASE_IS_INVALID to get it to reset the whole pool.

Upvotes: 1

Related Questions