MySQL Bugs: #31353: Socket hangs in ReadAheadInputStream.fill()

Bug #31353	Socket hangs in ReadAheadInputStream.fill()
Submitted:	2 Oct 2007 20:21	Modified:	18 Nov 2010 7:09
Reporter:	o s	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	Connector / J	Severity:	S2 (Serious)
Version:	5.0.7	OS:	Linux (Fedora Core 3)
Assigned to:		CPU Architecture:	Any

Description:
Communication with the database is hanging sporadically. If I don't set the socketTimeout property, it will hang forever. With the socketTimeout property, I get the following exception:

-------
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

** BEGIN NESTED EXCEPTION **

java.net.SocketTimeoutException
MESSAGE: Read timed out

STACKTRACE:

java.net.SocketTimeoutException: Read timed out
       at java.net.SocketInputStream.socketRead0(Native Method)
       at java.net.SocketInputStream.read(SocketInputStream.java:129)
       at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
       at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
       at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
       at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994)
       at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2411)
       at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916)
       at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
       at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
       at com.mysql.jdbc.Connection.execSQL(Connection.java:3250)
       at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1355)
       at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1270)
       at org.apache.commons.dbcp.DelegatingStatement.executeUpdate(DelegatingStatement.java:228)
...
---------

The MySQL server resides on a different machine from the JVM. The MySQL server version is 4.1.21 and 4.1.22 (I tried both).

The exception can occur on updates or selects, InnoDB or MyISAM. Two facts which may help:

* It occurs on large updates/selects. This is *not* because the database operation takes a long time--the query/statement never shows up in "SHOW PROCESSLIST" commands. Often the query/statement itself is long, containing a large (though not unreasonably so) "IN()" clause.

* It occurs on connections that have been idle in the pool for a while (commons dbcp 1.2.2, commons pool 1.3). 

I've exhausted every avenue in trying to debug this. I've upgraded the JVM (issue exists on both jdk1.5.0_07 and jdk1.6.0_02). I test each connection every time it's borrowed ("SELECT 1;").

The problem is either with MySQL, the JVM, or the OS socket. I've never had any issues with the network connection between the JVM and the MySQL Server.

Bug 9515 seems very similar to mine but it was closed as non-reproducible:

http://bugs.mysql.com/bug.php?id=9515

If there's any other information you need, please let me know.

Thanks.

How to repeat:
There is no set of steps guaranteed to generate this error. It happens once in a while in a production environment.

Another report of this issue:

http://forums.mysql.com/read.php?39,128693,174185#msg-174185

I am 90% confident that this is a bug in the MySQL driver.

I'd greatly appreciate any feedback.

After further investigation it looks like this issue only arises when using DBCP 1.2.2 and not 1.2.1.

It's likely the bug is in the DBCP code and not they MySQL driver code.

I'm currently looking through DBCP's changelog to find the exact cause but the MySQL Driver authors are in a better position than I am to identify the cause of this issue.

Hi and thanks for your report. Any news regarding your investigation?

I've opened an issue against commons DBCP.

The problem only occurs with DBCP 1.2.2, and not the older 1.2.1 which leads me to believe DBCP is at fault.

It's difficult to diagnose the exact cause. Can you think of any potential causes? The connection is trying to read from the socket when there's no data to read, so it hangs.

I don't wish to add to the DBCP debate; but we are running with an older version 1.2 and it fails.

However, if we run with an older MySQL JAR file (3.x) then it works fine.

Alan, no problem. Everybody is welcomed to post their opinion. Now if I can interest both of you in putting "traceProtocol=true" in your connect string on for awhile so we can examine what is happening?

There is also a good discussion in Bug#9515 with workaround provided in last two posts.

The workaround in bug #9515 does not apply to my situation.

I am setting the socketTimeout property in the connection string (equivalent to invoking setSoTimeout on each connection). This results in a SocketTimeoutException instead of a stuck thread. I explicitly close each connection in a finally clause. I am not misusing any APIs.

I've isolated the issue to DBCP 1.2.2. If the bug is in the MySQL driver code, it is in the MysqlPooledConnection or its related classes.

What is the performance hit associated with traceProtocol? I don't think I can enable it in a production environment.

Hi. I am sorry but I don't have production environment here nor there are two alike in the world, so I can't tell you of penalty. But, if you do not provide us with more info, we shall not be able to identify the problem...

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

I have the same problem that locks my DBCP pool
Any ideas so far why the Socket get stuck?

My dump is below.

"http-10.12.74.7-443-Processor24" daemon prio=1 tid=0x0966d388 nid=0x4849 runnable [0x2716f000..0x27171eb0]
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
	- locked <0x360347c8> (a com.mysql.jdbc.util.ReadAheadInputStream)
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1910)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2304)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2803)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
	at com.mysql.jdbc.Connection.execSQL(Connection.java:3170)
	- locked <0x3602a690> (a java.lang.Object)
	at com.mysql.jdbc.Connection.rollbackNoChecks(Connection.java:5191)
	at com.mysql.jdbc.Connection.rollback(Connection.java:5099)
	- locked <0x3602a690> (a java.lang.Object)
	at com.mysql.jdbc.Connection.realClose(Connection.java:4743)
	at com.mysql.jdbc.Connection.close(Connection.java:2172)
	at org.apache.commons.dbcp.DelegatingConnection.close(DelegatingConnection.java:214)
	at org.apache.commons.dbcp.PoolableConnection.reallyClose(PoolableConnection.java:102)
	at org.apache.commons.dbcp.PoolableConnectionFactory.destroyObject(PoolableConnectionFactory.java:305)
	at org.apache.commons.pool.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:883)
	- locked <0x35fb5f90> (a org.apache.commons.dbcp.AbandonedObjectPool)
	at org.apache.commons.dbcp.AbandonedObjectPool.invalidateObject(AbandonedObjectPool.java:130)
	at org.apache.commons.dbcp.AbandonedObjectPool.removeAbandoned(AbandonedObjectPool.java:163)
	at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:82)
	at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
	at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
	at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
	at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
	at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
	at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)

I fear we have many problems at once here... Let's try to check each one of them...

*Socket timeouts*:
UNCLOSED socket connection; JVM specs tell us GC does NOT release these resources thus they exhaust JVM resources related to socket operation, leading to SocketInputStream hanging your program. Always close the connection and use Socket.setSoTimeout(int) on every connection.

Now this is in relation with *pooled connections* and DBCP (or "why does 1.2.1 work", from Bug#30990):
If you're using a connection pool that _doesn't_ use the ConnectionPoolDataSource API to create connections that have lifecycle callbacks, then it is the _pool's_ responsibility to cleanup "logical" pooled connections when they're returned to the pool. Otherwise there is no way for a JDBC driver to tell that a connection is being pooled "above" it, and thus no event/method call where one can hook in to determine that you've been "logically" closed and returned to the pool.
More recent version of DBCP automatically call rollback() on connections that are returned to the pool.
You can see whether this is happening or not by looking at MySQL's "general" query log on the mysql server side of things, or by adding "profileSQL=true" to your JDBC URL configuration properties (DBCP 1.2.1, a somewhat older release does take care of sending rollback() on connections returned to a pool).
If we can show that for this case, Connector/J is flowing a commit() or rollback() to the database for all of connections, then this is more than likely a MySQL server bug, since the only "lock release" mechanisms a client has at a transactional level is sending "commit" or "rollback" to the server.

*Network*, resources and streaming resultset:
We do not know yet if MySQL server is restarting/crashing during your tests but I'll presume it is not. To work around network problems I suggest turning streaming on:
Use SS PP statements in your connect string
Open statement like this:
Statement statement = connection.createStatement(java.sql.ResultSet.TYPE_FORWARD_ONLY, java.sql.ResultSet.CONCUR_READ_ONLY);
statement.setFetchSize(Integer.MIN_VALUE); // << you may vary this value till you hit problem no more, ie. 1000. Integer.MIN_VALUE means row-by-row
Increase statement query timeout until problem is gone:
statement.setQueryTimeout(864000); //xxx
Make sure "holdResultsOpenOverStatementClose" in your connection string is set to false.
Try adding " -XX:+UseParallelGC" to your JVM settings and see if it helps.

I'm having a similar issue except without using DBCP. I'm just using a raw connection acquired from DriverManager and I'm doing a very large select on the database. I've used Statement.setFetchSize(Integer.MIN_VALUE) to force the driver to not buffer the whole result because I run out of memory otherwise, and I tried adding 'useUnbufferedInput=true&useReadAheadInput=false' to the connection string per #9515 with no luck. I do get some number of rows and then it hangs with this stack:

ava.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2428)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2938)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:910)
com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1405)

With traceProtocol on, the last few entries look like:

Wed May 21 11:17:51 CDT 2008 TRACE: Reading reusable packet of length 94
Packet header:
5e 00 00 37                 ^ . . 7 

Wed May 21 11:17:51 CDT 2008 TRACE: reuseAndReadPacket() payload:
01 33 17 57 45 42 2d 43     . 3 . W E B - C 
47 49 20 63 61 6c 65 6e     G I . c a l e n 
64 61 72 20 61 63 63 65     d a r . a c c e 
73 73 0f 61 74 74 65 6d     s s . a t t e m 
70 74 65 64 2d 72 65 63     p t e d - r e c 
6f 6e 01 32 13 32 30 30     o n . 2 . 2 0 0 
38 2d 30 31 2d 30 31 20     8 - 0 1 - 0 1 . 
32 32 3a 31 30 3a 30 31     2 2 : 1 0 : 0 1 
09 34 31 37 34 31 35 31     . 4 1 7 4 1 5 1 
31 30 09 32 30 33 30 32     1 0 . 2 0 3 0 2 
36 33 30 37 01 36 04 31     6 3 0 7 . 6 . 1 
35 37 34 02 38 30           5 7 4 . 8 0 

Event at 2008-01-01 22:10:01.0

Wed May 21 11:17:51 CDT 2008 TRACE: Reading reusable packet of length 95
Packet header:
5f 00 00 38                 _ . . 8 

Wed May 21 11:17:51 CDT 2008 TRACE: reuseAndReadPacket() payload:
01 33 17 57 45 42 2d 43     . 3 . W E B - C 
47 49 20 63 61 6c 65 6e     G I . c a l e n 
64 61 72 20 61 63 63 65     d a r . a c c e 
73 73 0f 61 74 74 65 6d     s s . a t t e m 
70 74 65 64 2d 72 65 63     p t e d - r e c 
6f 6e 01 32 13 32 30 30     o n . 2 . 2 0 0 
38 2d 30 31 2d 30 31 20     8 - 0 1 - 0 1 . 
32 32 3a 31 30 3a 32 32     2 2 : 1 0 : 2 2 
0a 31 32 38 33 31 39 31     . 1 2 8 3 1 9 1 
35 31 35 09 32 30 33 30     5 1 5 . 2 0 3 0 
32 36 33 30 37 01 36 04     2 6 3 0 7 . 6 . 
33 36 36 30 02 38 30        3 6 6 0 . 8 0 

Event at 2008-01-01 22:10:22.0

Wed May 21 11:17:51 CDT 2008 TRACE: Reading reusable packet of length 95
Packet header:
5f 00 00 39                 _ . . 9

So it looks like it's trying to read the entry and then waiting for the data to come from the database. DB and app are on the same server.

I'm using MySQL connector 5.1.6 with MySQL 5.0.51a-3ubuntu5

Thanks,

Derek

Description:
In a multi threaded application(webapp), in which many threads want to access the database,the system will hang,  cpu 100%, 5-10minutes system become available  again。We dump thread,many runnable thread like below,
 
"catalina-exec-221" daemon prio=1 tid=0x00002aab0c2f9aa0 nid=0x7f7b runnable [0x0000000045338000..0x0000000045339d00]
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
	- locked <0x00002aaacda57eb8> (a com.mysql.jdbc.util.ReadAheadInputStream)
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1931)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2380)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2909)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1600)
	at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1125)
	- locked <0x00002aaacda48010> (a java.lang.Object)
	at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:677)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1357)
	- locked <0x00002aaacda48010> (a java.lang.Object)
	- locked <0x00002aaab87b89a8> (a com.mysql.jdbc.ServerPreparedStatement)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1274)
	- locked <0x00002aaab87b89a8> (a com.mysql.jdbc.ServerPreparedStatement)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1259)
	- locked <0x00002aaab87b89a8> (a com.mysql.jdbc.ServerPreparedStatement)
	at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102)
	at org.apache.commons.dbutils.QueryRunner.update(QueryRunner.java:419

It happens some times every day  in a production environment。

The production environment run normally in 4 years. Recently changes：use PreparedStatement.addBatch()  method  to  commit  many update/insert sqls(Previously,comit single sql one by one)。

I'm experiencing this problem as well. Has the cause been determined?

Periodically, a large number of HTTP threads in my Tomcat web application get stuck in ReadAheadInputStream.fill(ReadAheadInputStream.java:113) (see stack trace below). We're running in a clustered environment with multiple app servers connecting to the same database. The problem seems to originate at the database because multiple servers in the cluster experience the problem at the same time.

I'm using Connector/J 5.1.8, MySQL Community Server (GPL) 5.0.84-log x86_64. wait_timeout is set to 28800, net_write_timeout is set to 3600. Database and application running on Linux (CentOS 5).

Any help would be appreciated!

"http-80-33" daemon prio=10 tid=0x0000002c4b5f7c00 nid=0x5235 runnable [0x0000000046b92000..0x0000000046b93e30]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
	- locked <0x0000002b35893560> (a com.mysql.jdbc.util.ReadAheadInputStream)

I had this problem in the past and I thought it was related to prematurely stopping queries with ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY and setFetchSize(Integer.MIN_VALUE). I didn't see it when letting the query run or with a normal select query. I ended up restarting the mysql server to fix the hang and I had figured it was a server problem.

Now I've seen it with a simple select query on a new connection right after application startup. It also happened after a server restart. I'm using the latest JVM (Sun 1.6.0_17) and Connector/J (5.1.10). The server is 5.0.51a.

I found this bug that references the query cache.

http://bugs.mysql.com/bug.php?id=34176

After adding SQL_NO_CACHE to my select SQL, the hang has completely disappeared. I can't say if this is really a query cache bug, or even where the bug originates, the client or server operating system, MySQL server, JVM, JDK or Connector/J. This appears to work around it somehow.

Brad, you're probably right and this is a cache problem. I think it should also cause "sleeping" connections to appear in process-list.

I am having the same problem.  I'm not using pooling, and as far as I can tell I am closing all connections/statements, etc.  The bug manifests itself every time on the second query after application startup. By adding SQL_NO_CACHE to the offending query the problem appears to have gone away.

Details:
OS: 2.6.28-15-generic #52-Ubuntu SMP
MySQL: MySQL 5.0.75-0ubuntu10.2
JDBC: mysql-connector-java v5.1.10
JVM: Sun v1.6.0_16
SQL: SELECT date, open, high, low, close, avg_inc_30d, avg_dec_30d FROM eod_eqt WHERE product_id = ? ORDER BY date ASC
eod_eqt has +4.2M rows

Hi,

Even we faced the similar issue for the first time and we were not able to reproduce the same.
We had a thread pool of size 10 and all these 10 threads got stuck with the below exception when we captured the thread dump of the tomcat process.
-------------------------------------------------------------------------
"pool-4-thread-10" prio=10 tid=0x00002aabdc97a000 nid=0x4df5 runnable [0x0000000045eb2000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java)
	- locked <0x00002aab1ce5aa88> (a com.mysql.jdbc.util.ReadAheadInputStream)
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java)
	- locked <0x00002aab1ce65180> (a java.lang.Object)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java)
	at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java)
	- locked <0x00002aab1ce65180> (a java.lang.Object)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
	at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
	at org.hibernate.loader.Loader.getResultSet(Loader.java:1778)
	at org.hibernate.loader.Loader.doQuery(Loader.java:662)
	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
	at org.hibernate.loader.Loader.doList(Loader.java:2211)
	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
	at org.hibernate.loader.Loader.list(Loader.java:2090)
	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)
	at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
	at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
	at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
	at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:66)
	at com.hp.cloudprint.jef.entities.dao.impl.AbstractHibernateDAO.executeQuery(AbstractHibernateDAO.java:86)
	at com.hp.cloudprint.jef.entities.dao.impl.JEFDAOImpl.getJobFlowDataNextInSequence(JEFDAOImpl.java:263)
	at sun.reflect.GeneratedMethodAccessor103.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:307)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at $Proxy40.getJobFlowDataNextInSequence(Unknown Source)
	at com.hp.cloudprint.jef.wrkr.fsm.JobFlowLetState.getAnalyzedDSN(JobFlowLetState.java:775)
	at com.hp.cloudprint.jef.wrkr.fsm.DeliverCheck.continueDeliver(DeliverCheck.java:146)
	at sun.reflect.GeneratedMethodAccessor256.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.hp.cloudprint.jef.wrkr.fsm.PerJobFlowLetFSM.processEvent(PerJobFlowLetFSM.java:116)
	at com.hp.cloudprint.jef.wrkr.fsm.PerJobFlowLetController.call(PerJobFlowLetController.java:85)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

-------------------------------------------------------------------------

Due to the above behaviour we were forced to restart the tomcat.
One solution could be setting the socketTimeOut.
But still could anybody tell when does this happen and what's the root cause for the thread to hang?

Senthil, as I said two and a half years ago:
 [29 Feb 2008 11:28] Tonci Grgin
*Socket timeouts*: 
UNCLOSED socket connection; JVM specs tell us GC does NOT release these resources thus they exhaust JVM resources related to socket operation, leading to SocketInputStream hanging your program. Always close the connection and use Socket.setSoTimeout(int) on every connection.

or it might be a cache... Hard to reproduce, even harder to trace.

Thread dumps like this can be any number of things, the query cache bug referenced earlier, genuine database-level deadlock caused by your application, etc. It's more an issue if an error is *never* raised (deadlock timeout), the query cache bug is ruled out (disable it), or if it can be reproduced with a single thread.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

The problem still exists and has nothing to do with hibernate or the Apache Common connection pooling...  We are seeing the same thing in plain JDBC:

JVM 1.6_20
MySQL 5.1

"main" prio=10 tid=0x0000000040915800 nid=0x3faa runnable [0x00007f107979d000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
	- locked <0x00007f0fb6646ab0> (a com.mysql.jdbc.util.ReadAheadInputStream)
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2329)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2830)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2763)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3299)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:894)
	at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1382)
	at com.mysql.jdbc.RowDataDynamic.nextRecord(RowDataDynamic.java:409)
	at com.mysql.jdbc.RowDataDynamic.next(RowDataDynamic.java:388)
	at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:7027)

I have the same problem on production:

JBoss EAP 5.0.1 (with all patches)
Connector/J 5.1.13
RHEL 5.5
JDK 6.0 u21

The following thread is hanging for about 2 hours:

hread: ajp-192.168.200.1-8009-65 : priority:5, demon:true, threadId:701, threadState:RUNNABLE

                java.net.SocketInputStream.socketRead0(Native Method)
                java.net.SocketInputStream.read(SocketInputStream.java:129)
                com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
                com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
                com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
                - locked <0x71d24681> (a com.mysql.jdbc.util.ReadAheadInputStream)
                com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
                com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
                com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
                com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
                com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
                com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:3985)
                com.mysql.jdbc.ConnectionImpl.ping(ConnectionImpl.java:3962)
                sun.reflect.GeneratedMethodAccessor249.invoke(Unknown Source)
                sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                java.lang.reflect.Method.invoke(Method.java:597)
                org.jboss.resource.adapter.jdbc.vendor.MySQLValidConnectionChecker.isValidConnection(MySQLValidConnectionChecker.java:81)
                org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:559)
                org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:321)
                org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory.matchManagedConnections(LocalManagedConnectionFactory.java:402)
                org.jboss.resource.connectionmanager.InternalManagedConnectionPool.getConnection(InternalManagedConnectionPool.java:219)
                org.jboss.resource.connectionmanager.JBossManagedConnectionPool$BasePool.getConnection(JBossManagedConnectionPool.java:659)
                org.jboss.resource.connectionmanager.BaseConnectionManager2.getManagedConnection(BaseConnectionManager2.java:404)
                org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:381)
                org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:496)
                org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:941)
                org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:89)

I'm troubleshooting one application and it seems that sometimes (under load) 2 threads is using the same Connection (an application bug).

When the developers fixed the application (1 connection per thread), the hang has never happened again.

Allan, this might be the source of the problem... Things *might* be thread-safe but that does not mean they are *sharable* across the threads. This is a common mistake.

Sorry... the problem happened one more time... But now it is happening less frequently.

Judging by everything said here, this appears not to be c/J bug. Please review the problem report carefully for several workarounds that might help in your actual case.