net.sourceforge.jtds.jdbc.ResponseStream.getPacket locked

这几天出现一个异常奇怪的问题。都是出现在顶层连接上面。

环境： jdk1.6， sqlserver2012

程序总是莫名其妙的死掉， 

java thread dump文件如下： 出现N多一下片段。

http-12345-13" daemon prio=6 tid=0x0000000024140800 nid=0x1c75c runnable [0x0000000032e1e000]
   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:846)
at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:727)
- locked <0x000000000dfb9148> (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:3932)
at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
- locked <0x000000000dfb94e0> (a net.sourceforge.jtds.jdbc.TdsCore)
at net.sourceforge.jtds.jdbc.TdsCore.submitSQL(TdsCore.java:899)
at net.sourceforge.jtds.jdbc.ConnectionJDBC2.rollback(ConnectionJDBC2.java:2109)
- locked <0x000000000dfb92c8> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
at com.mchange.v2.c3p0.impl.C3P0ImplUtils.resetTxnState(C3P0ImplUtils.java:275)
at com.mchange.v2.c3p0.impl.NewPooledConnection.reset(NewPooledConnection.java:332)
at com.mchange.v2.c3p0.impl.NewPooledConnection.markClosedProxyConnection(NewPooledConnection.java:313)
- locked <0x000000000e10b798> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
at com.mchange.v2.c3p0.impl.NewProxyConnection.close(NewProxyConnection.java:1246)
- locked <0x000000001a0b9120> (a com.mchange.v2.c3p0.impl.NewProxyConnection)
at org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(DataSourceUtils.java:277)
at org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSourceUtils.java:238)
at org.springframework.jdbc.datasource.DataSourceUtils$ConnectionSynchronization.beforeCompletion(DataSourceUtils.java:366)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCompletion(AbstractPlatformTransactionManager.java:674)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:483)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:176)
at $Proxy110.getStepNames(Unknown Source)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2" daemon prio=6 tid=0x000000001fc6d800 nid=0x17a04 waiting for monitor entry [0x000000002806f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at com.mchange.v2.c3p0.impl.NewPooledConnection.getConnection(NewPooledConnection.java:149)
- locked <0x000000000df99388> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:284)
at com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1606)
at com.mchange.v2.resourcepool.BasicResourcePool.access$200(BasicResourcePool.java:32)
at com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1228)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

"http-12345-2" daemon prio=6 tid=0x00000000243e7000 nid=0x13c7c waiting for monitor entry [0x0000000031e1e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.Arrays.copyOf(Arrays.java:2882)
at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
at java.lang.StringBuffer.append(StringBuffer.java:224)
- locked <0x000000001a49c670> (a java.lang.StringBuffer)
at com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1644)
at com.mchange.v2.resourcepool.BasicResourcePool.checkinResource(BasicResourcePool.java:658)
- locked <0x000000000dee9c48> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$ConnectionEventListenerImpl.doCheckinResource(C3P0PooledConnectionPool.java:636)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$ConnectionEventListenerImpl.connectionClosed(C3P0PooledConnectionPool.java:630)
at com.mchange.v2.c3p0.util.ConnectionEventSupport.fireConnectionClosed(ConnectionEventSupport.java:55)
at com.mchange.v2.c3p0.impl.NewPooledConnection.fireConnectionClosed(NewPooledConnection.java:439)
at com.mchange.v2.c3p0.impl.NewPooledConnection.markClosedProxyConnection(NewPooledConnection.java:326)
- locked <0x000000000df99388> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
at com.mchange.v2.c3p0.impl.NewProxyConnection.close(NewProxyConnection.java:1246)
- locked <0x000000001a069638> (a com.mchange.v2.c3p0.impl.NewProxyConnection)
at org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(DataSourceUtils.java:277)
at org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSourceUtils.java:238)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCleanupAfterCompletion(DataSourceTransactionManager.java:296)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(AbstractPlatformTransactionManager.java:750)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:537)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:469)
at org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:266)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:170)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:176)
at $Proxy30.tableGet(Unknown Source)

杯具的是， jdts如是回答这个问题， 真扯

http://sourceforge.net/p/jtds/bugs/621/

#621 Hang in SocketRead

继续搜索， 竟然发现一个这个说法， 大神啊， 不管行不行， 先试试， 测试要等周一了。

http://www.blogjava.net/diggbag/articles/360263.html

1.出现的问题
  日志文件没有新的输出。

2.问题分析
  dump出堆栈，如下：
  "main" prio=10 tid=0x000000005de12000 nid=0x27e8 runnable [0x0000000040240000]
   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:842)
    at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:723)
    - locked <0x0000000759fd9f90> (a java.util.ArrayList)
    at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
    at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:135)
    at net.sourceforge.jtds.jdbc.ResponseStream.readString(ResponseStream.java:290)
    at net.sourceforge.jtds.jdbc.ResponseStream.readNonUnicodeString(ResponseStream.java:274)
    at net.sourceforge.jtds.jdbc.TdsData.readData(TdsData.java:936)
    at net.sourceforge.jtds.jdbc.TdsCore.tdsRowToken(TdsCore.java:3007)
    at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2270)
    at net.sourceforge.jtds.jdbc.TdsCore.getNextRow(TdsCore.java:765)
    at net.sourceforge.jtds.jdbc.JtdsResultSet.next(JtdsResultSet.java:596)
    at org.apache.commons.dbcp.DelegatingResultSet.next(DelegatingResultSet.java:207)
    at org.apache.commons.dbcp.DelegatingResultSet.next(DelegatingResultSet.java:207)
    at com.jd.cis.worker.OppProductWorker.importData(OppProductWorker.java:310)
    at com.jd.cis.worker.BaseWorker.importDataSource(BaseWorker.java:416)
    at com.jd.cis.worker.OppProductWorker.doRun(OppProductWorker.java:276)
    at com.jd.cis.worker.BaseWorker.run(BaseWorker.java:448)
    at com.jd.cis.worker.OppProductWorker.main(OppProductWorker.java:564)

    上面有锁，对应的代码为
    statement.setFetchSize(1000);
    .....
    resultSet = statement.executeQuery();
    while (resultSet.next()) {
       ......
    }
    查询相关文档，了解到JTDS默认的socketTimeout为0，即读取数据没有超时时间。
    当数据链接意外终止的时候，JDTS可能检测不到，就会一直等待数据，阻塞进程。

    在本地重现该问题，在循环体里面设置断点，进入断点后，断掉所有网络链接，取消断点，继续运行，发现程序被一致阻塞了。
    当设置socketTimeout为60秒，重试，程序阻塞60秒后抛出异常。

    该问题在查询SQLServer数据库，大数据量查询，分批获取的时候，容易出现
    
3.解决方案
  为jdts的url链接中加上socketTimeout（单位秒）的设置，或在dbcp中如下设置
  <property name="connectionProperties" value="characterEncoding=UTF-8;socketTimeout=60"/>
  这个参数和mybatis的defaultStatementTimeout 参数是不一样的

  同时Worker中加入异常捕获重试机制

后注：  2013.09.11 在客户现场升级了sql server2012 数据库sp1补丁， 更换了数据库连接池 c3p0改成driud ， 添加了jdts的连接串 socketTimeout ， 经过这几个改进后， 目前系统稳定。