Re: [c3p0-users] Test on Checkout succeeding when connection has been dropped?
Status: Beta
Brought to you by:
swaldman
Menu
▾
▴
Re: [c3p0-users] Test on Checkout succeeding when connection has been dropped?
|
From: Steve W. <swa...@mc...> - 2013-07-11 12:03:07
|
hi,
have you set a preferredTestQuery? if so what is it? it's common to use very simple, very fast queries like SELECT 1, and that seems to work fine for a lot of set-ups. but in theory it's hazardous, a clever JDBC driver might resolve that one locally leading to an unreliable test for more elaborate queries. as a quick check, you might not set any preferredTestQuery at all, in which case c3p0 will fall back on a slow but reliable query to the database metadata. Does this still happen using the default test?
smiles,
Steve
On Jul 11, 2013, at 1:24 PM, Gustav Karlsson wrote:
> Hi,
>
> We are experiencing a strange behavior of our connection pool: We get a read-timeout when executing a simple query even after the connection-test on checkout has suceeded. This occurrs typically at night after a period of low activity, leading us believe that the read-timeout may be caused by the connection having been dropped by a firewall (due to inactivity).
>
>
> 01:39:55.762 [server] [scheduler-3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on CHECKOUT.
> 01:39:55.764 [server] [scheduler-3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on CHECKOUT has SUCCEEDED.
> 01:40:05.779 [server] [scheduler-3] [ ] DEBUG c.m.v2.c3p0.impl.NewPooledConnection - com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb handling a throwable.
> 01:40:05.788 [server] [scheduler-3] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - Resource com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb marked broken by pool (com.mchange.v2.resourcepool.BasicResourcePool@31482ac5).
> 01:40:05.790 [server] [scheduler-3] [ ] ERROR o.s.s.s.TaskUtils$LoggingErrorHandler - Unexpected error occurred in scheduled task.
> org.springframework.dao.DataAccessResourceFailureException: PreparedStatementCallback; SQL [select count(*) from ...]; I/U-feil: Socket read timed out; nested exception is java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
>
>
>
> Does anyone have any tips as to how the checkout-test can succeed when it seems as though the connection is dropped? (If we assume that the read-timeout is not caused by a slow query)
>
> We are using c3p0 v0.9.1.2 against an Orable 11g database. See full trace from c3p0 below.
>
>
> Regards,
> Gustav
>
>
>
> ...
> 1:39:09.341 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on IDLE CHECK.
> 01:39:09.341 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@4e514440] on IDLE CHECK.
> 01:39:09.342 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@256e3879] on IDLE CHECK.
> 01:39:09.343 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on IDLE CHECK has SUCCEEDED.
> 01:39:09.342 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@5bd13aa] on IDLE CHECK.
> 01:39:09.342 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@662ae1c9] on IDLE CHECK.
> 01:39:09.344 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@5bd13aa] on IDLE CHECK has SUCCEEDED.
> 01:39:09.344 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@662ae1c9] on IDLE CHECK has SUCCEEDED.
> 01:39:09.344 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@4e514440] on IDLE CHECK has SUCCEEDED.
> 01:39:09.345 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@256e3879] on IDLE CHECK has SUCCEEDED.
> 01:39:55.762 [server] [scheduler-3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on CHECKOUT.
> 01:39:55.764 [server] [scheduler-3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb] on CHECKOUT has SUCCEEDED.
> 01:39:55.764 [server] [scheduler-3] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@31482ac5 [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@7ec2d0d0)
> 01:40:05.779 [server] [scheduler-3] [ ] DEBUG c.m.v2.c3p0.impl.NewPooledConnection - com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb handling a throwable.
> java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:876) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1275) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3576) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3620) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76) ~[c3p0-0.9.1.2.jar:0.9.1.2]
> at net.sf.log4jdbc.PreparedStatementSpy.executeQuery(PreparedStatementSpy.java:735) [log4jdbc-remix-0.2.7.jar:na]
> at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:644) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:587) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:637) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:666) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:674) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:729) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:745) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.queryForInt(JdbcTemplate.java:776) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> ...
> Caused by: oracle.net.ns.NetException: Socket read timed out
> at oracle.net.ns.Packet.receive(Packet.java:321) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.net.ns.DataPacket.receive(DataPacket.java:103) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> 01:40:05.781 [server] [scheduler-3] [ ] DEBUG com.mchange.v2.sql.SqlUtils - Attempted to convert SQLException to SQLException. Leaving it alone. [SQLState: 08006; errorCode: 17002]
> java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:876) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> Caused by: oracle.net.ns.NetException: Socket read timed out
> at oracle.net.ns.Packet.receive(Packet.java:321) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.net.ns.DataPacket.receive(DataPacket.java:103) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> 01:40:05.783 [server] [scheduler-3] [ ] DEBUG c.m.v.c.impl.DefaultConnectionTester - Testing a Connection in response to an Exception:
> java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:876) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> Caused by: oracle.net.ns.NetException: Socket read timed out
> at oracle.net.ns.Packet.receive(Packet.java:321) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> 01:40:05.784 [server] [scheduler-3] [ ] DEBUG c.m.v.c.impl.DefaultConnectionTester - Connection oracle.jdbc.driver.T4CConnection@3fdcc849 failed Connection test with an Exception! [query=select 1 from dual]
> java.sql.SQLRecoverableException: Lukket tilkobling
> at oracle.jdbc.driver.PhysicalConnection.createStatement(PhysicalConnection.java:3371) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.PhysicalConnection.createStatement(PhysicalConnection.java:3346) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:72) [c3p0-0.9.1.2.jar:0.9.1.2]
> ...
> 01:40:05.786 [server] [scheduler-3] [ ] DEBUG c.m.v2.c3p0.impl.NewPooledConnection - com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb invalidated by Exception.
> java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:876) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> Caused by: oracle.net.ns.NetException: Socket read timed out
> at oracle.net.ns.Packet.receive(Packet.java:321) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> 01:40:05.788 [server] [scheduler-3] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - CONNECTION ERROR OCCURRED!
> 01:40:05.788 [server] [scheduler-3] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - Resource com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb marked broken by pool (com.mchange.v2.resourcepool.BasicResourcePool@31482ac5).
> 01:40:05.788 [server] [scheduler-3] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - incremented pending_acquires: 1
> 01:40:05.788 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb
> 01:40:05.788 [server] [scheduler-3] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@31482ac5 [managed: 4, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@7ec2d0d0)
> 01:40:05.788 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb
> 01:40:05.789 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v2.c3p0.impl.NewPooledConnection - com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb closed by a client.
> java.lang.Exception: DEBUG -- CLOSE BY CLIENT STACK TRACE
> at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:566) [c3p0-0.9.1.2.jar:0.9.1.2]
> at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:234) [c3p0-0.9.1.2.jar:0.9.1.2]
> at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:470) [c3p0-0.9.1.2.jar:0.9.1.2]
> at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:964) [c3p0-0.9.1.2.jar:0.9.1.2]
> at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547) [c3p0-0.9.1.2.jar:0.9.1.2]
> 01:40:05.789 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb
> 01:40:05.789 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@35270bfb
> 01:40:05.790 [server] [scheduler-3] [ ] ERROR o.s.s.s.TaskUtils$LoggingErrorHandler - Unexpected error occurred in scheduled task.
> org.springframework.dao.DataAccessResourceFailureException: PreparedStatementCallback; SQL [select count(*) from ...]; I/U-feil: Socket read timed out; nested exception is java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:253) ~[spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) ~[spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:603) ~[spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:637) ~[spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
> ...
> Caused by: java.sql.SQLRecoverableException: I/U-feil: Socket read timed out
> at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:876) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> Caused by: oracle.net.ns.NetException: Socket read timed out
> at oracle.net.ns.Packet.receive(Packet.java:321) ~[ojdbc6-11.2.0.2.0.jar:11.2.0.2.0]
> ...
> 01:40:05.833 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] [ ] DEBUG c.m.v.c.i.C3P0PooledConnectionPool - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1Po...@69...quireResource() returning.
> 01:40:05.834 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@31482ac5 [managed: 5, unused: 5, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@7ec2d0d0)
> 01:40:05.834 [server] [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - decremented pending_acquires: 0
> 01:44:09.343 [server] [Timer-0] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - Refurbishing idle resources - Thu Jul 11 01:44:09 CEST 2013 [com.mchange.v2.resourcepool.BasicResourcePool@31482ac5]
> 01:44:09.343 [server] [Timer-0] [ ] DEBUG c.m.v.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@31482ac5 [managed: 5, unused: 5, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@7ec2d0d0)
>
>
>
> ------------------------------------------------------------------------------
> See everything from the browser to the database with AppDynamics
> Get end-to-end visibility with application monitoring from AppDynamics
> Isolate bottlenecks and diagnose root cause in seconds.
> Start your free trial of AppDynamics Pro today!
> http://pubads.g.doubleclick.net/gampad/clk?id=48808831&iu=/4140/ostg.clktrk
> _______________________________________________
> c3p0-users mailing list
> c3p...@li...
> https://lists.sourceforge.net/lists/listinfo/c3p0-users
|