| Bug #9515 | Long response waiting using Connector/J | ||
|---|---|---|---|
| Submitted: | 31 Mar 2005 8:11 | Modified: | 29 Jul 2005 15:57 |
| Reporter: | Konstantin Kirenko | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | Connector / J | Severity: | S1 (Critical) |
| Version: | 3.1.7 | OS: | Windows (WinXP) |
| Assigned to: | CPU Architecture: | Any | |
[31 Mar 2005 8:11]
Konstantin Kirenko
[31 Mar 2005 16:22]
Mark Matthews
Does the problem go away if you add 'useUnbufferedInput=true&useReadAheadInput=false' to your JDBC URL? If the problem does go away with those parameters, we'd need to see the output of your program (not using those two parameters), with the following parameter added to your JDBC URL to debug what's happening: 'traceProtocol=true'. We've had one other report of this happening, and it _appears_ that either the OS or JVM is misinforming the driver about how many bytes are available to read off the socket, so the driver asks for more than will ever come down the wire.
[14 Apr 2005 11:59]
Konstantin Kirenko
Requested program output with tracing turned on
Attachment: finalStop.log (application/octet-stream, text), 75.27 KiB.
[14 Apr 2005 12:03]
Konstantin Kirenko
> Does the problem go away if you add > 'useUnbufferedInput=true&useReadAheadInput=false' to your JDBC URL? No, the problem still exists. > If the problem does go away with those parameters, we'd need to see the output > of your program (not using those two parameters), with the following parameter > added to your JDBC URL to debug what's happening: > > 'traceProtocol=true'. > > We've had one other report of this happening, and it _appears_ that either the > OS or JVM is misinforming the driver about how many bytes are available to read > off the socket, so the driver asks for more than will ever come down the wire. Seems like our application is stopped after a long period of time. According to our opinion time duration depends on quantity of bytes which are allocated for PreparedStatement objects. Here is traceProtocol log "(not using those two parameters)".
[27 Apr 2005 8:03]
Konstantin Kirenko
Are there any progress regarding this issue? Do you need any additional information?
[27 May 2005 23:00]
Bugs System
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".
[30 May 2005 10:02]
Konstantin Kirenko
Why this bug is turned to 'No Feedback' state? I've uploaded the file with log and answered asked questions. What else need for this bug?
[30 May 2005 10:15]
Tobias Jenkner
I got the same problem - I will try it without buffering too. are there any major performance disadvantages with buffering disabled? greets, Tobias.
[30 May 2005 11:30]
Vasily Kishkin
I tried to reporoduce this bug but I was not able to do it. Could you please write here any simple test case ? How many records must be in the table ?
[30 May 2005 12:26]
Konstantin Kirenko
Unfortunately we haven't got a simple test case now. We are working on it. Seems like this bug doesn't depend on the quantity of records in a table. Seems like it depends how many times prepareStatement object is produced with the same SQL and the same parameters for the table.
[31 May 2005 15:20]
Tobias Jenkner
When I take a look in MySQL Administrator there is no connection listed there that matches the connection parameters client thread that hangs. The connection is certainly timed out on the server. Shouldn't there occur an IOException on the client when this happens?
[18 Jun 2005 5:01]
Vasily Kishkin
Could you please try to change value of server options "net_read_timeout" and "wait_timeout" in my.ini ?
[20 Jun 2005 6:21]
Tobias Jenkner
change it to what values?
[26 Jun 2005 6:55]
Vasily Kishkin
Could you please write here definiton of table ? How many records ?
[29 Jun 2005 7:52]
Konstantin Kirenko
The table creation script is create table test ( field_1 char (2), field_2 varchar (10), field_3 varchar(30), field_4 varchar (10), field_5 varchar (10), field_6 varchar (10), field_7 int(1), field_8 varchar(30), field_9 varchar (20), field_10 varchar (1), field_11 varchar (1), field_12 varchar(30), field_13 real, field_14 real, field_15 real, field_16 real, field_17 varchar(30), field_18 varchar(30), field_19 varchar(30), field_20 varchar(30) ) TYPE = InnoDB; The number of records is approximately 200000. Seems like the problem appears when a lot of connections is open simultaneously. Please not OutOfMemory error is not appear during our tests.
[2 Jul 2005 8:40]
Vasily Kishkin
Sorry, I was not able to reproduce the bug. I started 20 test cases on my computer. But noone returned any error message. I attached my test case. I tested on mysql 4.1.13, Win 2000 Sp4 , JDK 1.5, JDBC 3.1.8.
[2 Jul 2005 8:41]
Vasily Kishkin
Test case
Attachment: 9515.zip (application/x-zip-compressed, text), 1.25 KiB.
[20 Jul 2005 17:30]
Jeremy Roy
We are experiencing this problem as well, using 4.1.9-standard with JDBC connector 3.1.10. Unfortunately I don't have a consistent way to reproduce, but our situation is consistent with the previous comments: it seems to happen more frequently with a larger number of open connections and with longer transactions. I have seen it in not just updates but also selects, always using InnoDB engine. Here are 3 different stack traces of threads that were hung waiting for a connection that didn't seem to be in the list of connections shown by "show processlist", long after the timeout period had expired: -------------------- java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(SocketInputStream.java:129) com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:105) com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:148) com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:176) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1899) com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2401) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:770) com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1288) com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2269) com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:421) com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:1959) com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1384) com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1133) com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:670) com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1024) java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(SocketInputStream.java:129) com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:145) com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:176) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1899) com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:519) com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:408) com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:1959) com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1384) com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1727) com.mysql.jdbc.Connection.execSQL(Connection.java:2972) com.mysql.jdbc.Connection.rollbackNoChecks(Connection.java:4794) com.mysql.jdbc.Connection.rollback(Connection.java:4691) org.apache.commons.dbcp.cpdsadapter.ConnectionImpl.rollback(ConnectionImpl.java:314) java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(SocketInputStream.java:129) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1391) com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:1538) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1929) com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1167) com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1278) com.mysql.jdbc.Connection.execSQL(Connection.java:2251) com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1772) com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1619)
[29 Jul 2005 14:15]
Jeremy Roy
I added the properties 'useUnbufferedInput=true&useReadAheadInput=false' to our application in production and the issue has occurred a few more times since my last comment. The relevant parts of the more recent stack traces are shown below. Connector/J 3.1.10, MySQL 4.1.9-standard, Fedora Core 3, kernel 2.6.9-1.667smp on a dual EMT64. ======================= java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(SocketInputStream.java:129) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1899) com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2401) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:770) com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1288) com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2258) com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:421) com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:1959) com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1384) com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1133) com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:670) com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1024) java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(SocketInputStream.java:129) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1899) com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2401) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858) com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:770) com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1288) com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2269) com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:421) com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:1959) com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1384) com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1727) com.mysql.jdbc.Connection.execSQL(Connection.java:2972) com.mysql.jdbc.Connection.execSQL(Connection.java:2902) com.mysql.jdbc.Statement.executeQuery(Statement.java:822)
[29 Jul 2005 14:15]
Jeremy Roy
Also, we occaisionally see exceptions (not "stuck" threads) as follows that appear possibly related to this issue. In at least the first instance, it looks like that exception occurred after the thread was "stuck" for about 15 minutes. The threads whose stack traces are shown above were stuck for hours each and the process was killed manually.
=======================
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:
** BEGIN NESTED EXCEPTION **
java.net.SocketException
MESSAGE: No route to host
STACKTRACE:
java.net.SocketException: No route to host
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1899)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2348)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
at com.mysql.jdbc.ServerPreparedStatement.serverResetStatement(ServerPreparedStatement.java:1350)
at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1142)
at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:670)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1024)
...
** END NESTED EXCEPTION **
Last packet sent to the server was 928551 ms ago.
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2560)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
at com.mysql.jdbc.ServerPreparedStatement.serverResetStatement(ServerPreparedStatement.java:1350)
at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1142)
at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:670)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1024)
...
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:
** BEGIN NESTED EXCEPTION **
java.net.SocketException
MESSAGE: Broken pipe
STACKTRACE:
java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2689)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2618)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1551)
at com.mysql.jdbc.ServerPreparedStatement.realClose(ServerPreparedStatement.java:877)
at com.mysql.jdbc.ServerPreparedStatement.close(ServerPreparedStatement.java:453)
...
[29 Jul 2005 15:49]
Mark Matthews
Do your application and database live on different machines? "No route to host" points at some pretty flakey networking going on, which would also cause the other issues you see.
[29 Jul 2005 15:55]
Jeremy Roy
They do (live on separate machines), but we have no indication of any network issues. There are many other simultaneous database queries going on at the time that these occur, with no issues.
[29 Jul 2005 15:57]
Mark Matthews
I can only say that "No route to host" exceptions don't happen on their own, and I'm really at a loss to explain how the JDBC driver can actually cause them.
[29 Jul 2005 16:03]
Jeremy Roy
We'll try some tests to isolate the network as a factor for this. In any case, is there a network problem that would cause it to hang indefinitely at the point(s) described above? Frankly, I am a lot more concerned about those than the "No route to host" exceptions-- at least those fail at some point and don't require me to restart the java process. An indefinite wait on I/O seems bad-- is there a timeout that can be set on MysqlIO.readFully through the JDBC params or something?
[29 Jul 2005 17:09]
Jeremy Roy
Nevermind, I found the socketTimeout and connectTimeout connection properties in the documentation.
[21 Nov 2005 12:04]
Mike Zhang
it seems to be the issue of JVM on Windows itself. I also encounter this problem, but there is no matter with MySQL JDBC Connector. My servlet (in apache Tomcat running on Windows 2000) generates a thread A, which also generates 20 threads B1-B20 to connect with remote hosts simultaneously. Thread A manages B1-B2 as "thread pool". My debug JSP file found the threads B1-B20 in the servlet hang at socketRead0() of java.net.SocketInputStream. This case emerges frequently after a lot of connection. anyone has more ideas on such problem, please notify me: mz24cn@hotmail.com
[21 Nov 2005 12:06]
Mike Zhang
>Nevermind, I found the socketTimeout and connectTimeout connection properties in the documentation. Jeremy Roy, I tried to interrupt the thread but it does not work. The state of thread is always "RUNNABLE". It seems no way to finish the thread gracefully.
[21 Nov 2005 15:44]
Mike Zhang
HI! Everybody! I find the key of the problem. It must be issued by UNCLOSED socket connection. Maybe your program normally close DB connection/socket connection when no Exception throwed. However, some connections are not closed (this is your program's problem. You should close the DB/socket connection in catch block!). Notes: the JVM specification tells us GC does NOT release these resources such as socket connection. After a lot of DB operations (many times of socket connection for my case), these unclosed connections exhaust JVM resources related with socket operation, leading to SocketInputStream hanging your program. This is my explanation!
[22 Nov 2005 11:12]
Mike Zhang
always close the connection and use Socket.setSoTimeout(int) on every connection, I solve my problem. the hanging does never appear again.
