jTDS socket hanging with C3P0 connection check (SQ

Question

Here is the environment:

• Java 5
• Web application running in Tomcat 6.0.18 on Windows (not sure the version)
• Database: SQL Server 2008 R2
• JDBC Driver: jTDS 1.2.5
• Connection pool provider: C3P0 0.9.1.2

I am trying to debug a problem that a client is having. Basically every couple weeks, our web application locks up on their server, and they can't access it. A restart fixes the issue. Further investigation shows that the reason everything is locked up is that everything is waiting on the database connections to return. I think the issue is likely with SQL Server, not C3P0.

What I believe is going on is that C3P0's "idle check query" is hanging. The query is this:

select * from c3p0_connection_test_table

It looks like this query is run, and the result is never returned. Here is what I see in my thread dump. Notice DefaultConnectionTester.activeCheckConnection(), which is the idle check:

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2" daemon prio=6 tid=0x0000000007c32000 nid=0x1250 runnable [0x000000001072f000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at java.io.DataInputStream.readFully(DataInputStream.java:178)
    at java.io.DataInputStream.readFully(DataInputStream.java:152)
    at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:841)
    at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:722)
    - locked <0x000000016ac03f48> (a java.util.ArrayList)
    at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
    at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
    at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
    at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3928)
    at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1045)
    - locked <0x000000016d965268> (a net.sourceforge.jtds.jdbc.TdsCore)
    at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:465)
    at net.sourceforge.jtds.jdbc.JtdsStatement.executeQuery(JtdsStatement.java:1301)
    at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:73)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:374)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:310)
    at com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:1999)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

But what could cause such a simple query to hang at reading from the socket? I don't believe there would be any database locking on this table, as it is completely managed by C3P0 and never inserted/updated. Also, any failed attempts to get connections from the pool (if this were the cause of the hanging), I would expect a stacktrace somewhere. Instead what I see is the app just locking up, because all future connection requests are waiting for this "idle check" to complete.

Here is one of the threads that is waiting for the "idle check" to complete:

    "http-80-3" daemon prio=6 tid=0x0000000007c33800 nid=0x122c in Object.wait() [0x000000001082d000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:579)
    - locked <0x0000000167a88a60> (a com.mchange.v2.resourcepool.BasicResourcePool)
    at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
    at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
    at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
    at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:142)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:85)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1354)
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
    at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at $Proxy15.getTransaction(Unknown Source)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:317)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at $Proxy79.getCrowdProperties(Unknown Source)
    at com.jamasoftware.contour.gateway.crowd.CrowdSsoServices.autoLogin(Unknown Source)
    at com.jamasoftware.contour.security.AutoLoginServicesManager.autoLogin(Unknown Source)
    at org.springframework.security.ui.rememberme.RememberMeProcessingFilter.doFilterHttp(RememberMeProcessingFilter.java:74)
    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at com.jamasoftware.contour.view.filter.CheckSetupFilter.doFilter(Unknown Source)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at org.springframework.security.concurrent.ConcurrentSessionFilter.doFilterHttp(ConcurrentSessionFilter.java:99)
    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at com.jamasoftware.contour.view.filter.ExpirationFilter.doFilter(Unknown Source)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at com.jamasoftware.contour.view.filter.GzipFilter.doFilter(Unknown Source)
    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
    at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
    at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:864)
    at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:579)
    at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1665)
    at java.lang.Thread.run(Thread.java:619)

From looking at C3P0's source code, the two lines at the top:

at java.lang.Object.wait(Native Method)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:579)

... only happen when the connection is waiting for the "idle check".

Unfortunately, this is a client, and I can't report the exact details of the environment here. But any suggestions I can take to them on our next call.

UPDATE:

Their application was locked up again today. Here are the things that we've tried so far:

• They have updated to the latest jTDS driver (1.2.5)
• I have set the socketTimeout property on the connection string to 300 but still the driver stays stuck on socketRead0() long after 5 minutes
• We changed the active check query from "select * from c3p0_connection_test_table" to "select 1"
• We have added the unreturnedConnectionTimeout and debugUnreturnedConnectionStackTraces properties to C3P0 (these aren't catching broken connections, though)

Here are all the C3P0 connection properties we have set:

    <property name="minPoolSize" value="1"/>
    <property name="maxPoolSize" value="30"/>
    <property name="acquireIncrement" value="3"/>
    <property name="automaticTestTable" value="c3p0_connection_test_table"/>
    <property name="idleConnectionTestPeriod" value="30"/>
    <property name="testConnectionOnCheckin" value="true"/>
    <property name="testConnectionOnCheckout" value="true"/>

One weird thing that happened was that while the application was locked up, we tried to log into SQL Server Management Studio with the application user, and it wouldn't let us in (I think it was just a normal timeout error). The database was started and listening on port 1433 (verified with telnet), so I think that means that the maximum number of connections to the database had been reached. I'm not sure if that helps determine the cause of this issue, though.

Leads followed without success:

• This person had an issue with operating systems, and potentially the number of NIC cards on the server
• An answerer below pointed me to a bug in an older version of jTDS here

Helpful answers can either ask me to check on something on the client's machine, or point me to a possible root cause. Whatever answers helps me track this down will get the bounty.

Answer 1

Was there also another thread closing a connection while the connection was being tested? Looks like C3P0 fixed this in c3p0-0.9.2-pre3:

-- Required tests of PooledConnections to own the locks associated with those PooledConnections in order to prevent occasional deadlocks when PooledConnection.close() coincides with a Connection test. Many thanks to an anonymous SourceForge user for calling attention to this issue.

from: https://github.com/swaldman/c3p0/blob/master/src/dist-static/CHANGELOG

Answer 2

I ran into a similar issue with c3p0 (0.9.1) hanging when connecting to sql server using jtds.

I solved it by not using c3p0 and just opening a connection whenever I needed one using DriverManager. I'm sure it is not as performant, but it works.

Answer 3

In sql server check if - properties - connections - ”Use query governor to prevent long-running queries” is disabled

Answer 4

First ideas: check they're using the latest jTDS version and SQL Server is patched and updated to latest SP!

There are some reports about this kind of behaviour in jTDS bug tracking, most notably this one. Apparently the SQL Server is closing the connection but jTDS doesn't notice.

In newer versions of jTDS there is a socketTimeout property (default=0), maybe this helps.

You could also test a different JDBC driver.