| Bug #31698 | Statement.setQueryTimeout(int) does not throw exception on timeout | ||
|---|---|---|---|
| Submitted: | 18 Oct 2007 19:16 | Modified: | 9 Apr 2009 15:50 |
| Reporter: | Cavan Morris | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | Connector / J | Severity: | S2 (Serious) |
| Version: | 5.1.5 | OS: | Linux (2.6.22.9-61.fc6) |
| Assigned to: | CPU Architecture: | Any | |
[18 Jan 2008 0:44]
Cavan Morris
Any updates on this bug??
[22 Apr 2008 6:47]
Tonci Grgin
Hi Cavan and please accept my apologies for the delay. I missed this report completely... Checking it now. Bug#36243 was marked as duplicate of this report.
[22 Apr 2008 7:06]
Tonci Grgin
Cavan, I have run our regression test and found no problems. If you can check on StatementTest.java in src\testsuite\simple of c/J sources and see what's different from your environment (you have provided no test case) please.
Test should be around line 538 in last sources.
public void testCancelStatement() throws Exception {
if (versionMeetsMinimum(5, 0)) {
Connection cancelConn = null;
[22 Apr 2008 7:11]
Tonci Grgin
And a simpler test in src\testsuite\regression\StatementRegressionTest.java:
public void testBug22359() throws Exception {
if (versionMeetsMinimum(5, 0)) {
Statement timeoutStmt = null;
try {
timeoutStmt = this.conn.createStatement();
timeoutStmt.setQueryTimeout(2);
long begin = System.currentTimeMillis();
try {
timeoutStmt.execute("SELECT SLEEP(30)");
fail("Query didn't time out");
} catch (MySQLTimeoutException timeoutEx) {
long end = System.currentTimeMillis();
assertTrue((end - begin) > 1000);
}
} finally {
if (timeoutStmt != null) {
timeoutStmt.close();
}
}
}
}
[22 Apr 2008 19:09]
Cavan Morris
Thanks for looking at this Tonci.
When I use your query, "select sleep(30)", I have no problem. However, if I run a long simple query, "select * from transaction_log", the problem is present. transaction_log is a table with several million rows.
Here is the code I ran based on your regression test:
public static void testBug22359() throws Exception {
Statement timeoutStmt = null;
Connection conn = null;
try {
//Get connection from pool.
conn = Db.getConnection(EpConstants.EPASSDB_HANDLE);
timeoutStmt = conn.createStatement();
timeoutStmt.setQueryTimeout(2);
long begin = System.currentTimeMillis();
try {
timeoutStmt.execute("SELECT * from Translog");
} catch (MySQLTimeoutException timeoutEx) {
long end = System.currentTimeMillis();
timeoutEx.printStackTrace();
}
} finally {
if (timeoutStmt != null) {
timeoutStmt.close();
}
if (conn != null) {
conn.close();
}
}
}
I see the query show up in a show processlist and then disappear after the timeout, but the Java thread continues to hang.
[22 Apr 2008 22:08]
Dave Lennert
I'm having the same problem. The JUnit code you quoted (from testBug22359() in src\testsuite\regression\StatementRegressionTest.java) fails for me. I'm using mysql-connector-java-5.1.6-bin.jar on Windows XP.
[24 Apr 2008 7:20]
Tonci Grgin
Dave, you need to run it from Eclipse against SVN repository. Cavan, I have taken your last remark into consideration. Will retry using large table (1000000+ rows). I am using JDK 1.5, are you by any chance using other JDK?
[24 Apr 2008 7:44]
Tonci Grgin
Cavan, I will need full, standalone test case from you that I can run without modifications on my machine. Just replace table name with "bug31698". I removed Try/Catch block from your code to see what happens and I can't find anything wrong: Server: 080424 9:29:34 3 Connect root@localhost on test --<cut>-- 3 Query select * from bug31698 -- 2 sec delay, not nearly enough for select to finish 080424 9:29:36 4 Connect root@localhost on test --<cut>-- 4 Query SET autocommit=1 4 Query KILL QUERY 3 4 Quit 3 Quit In client: .Loading JDBC driver 'com.mysql.jdbc.Driver' Done. Done. Connected to 5.0.58-pb1083-log java.vm.version : 1.5.0_12-b04 java.vm.vendor : Sun Microsystems Inc. java.runtime.version : 1.5.0_12-b04 os.name : Windows XP os.version : null sun.management.compiler : HotSpot Client Compiler E Time: 2,328 There was 1 error: 1) testBug31698(testsuite.simple.TestBug31698)java.sql.SQLException: Query execution was interrupted More than simplified test case based on our test framework (connection string options copied from you): try { this.stmt.setQueryTimeout(2); this.rs = this.stmt.executeQuery("select * from bug31698"); } finally { closeMemberJDBCResources(); } I am using # Changelog # $Id: CHANGES 6770 2008-04-15 00:23:33Z mmatthews $ nn-nn-08 - Version 5.1.7 but I don't see anything in changelog that would correct this problem. I think "Query execution was interrupted" is well enough in case like this, as it's what happened actually.
[24 Apr 2008 16:22]
Cavan Morris
Tonci, I have verified the problem on my end on both JDK1.5 and JDK1.6: >java -version java version "1.6.0_03" Java(TM) SE Runtime Environment (build 1.6.0_03-b05) Java HotSpot(TM) Client VM (build 1.6.0_03-b05, mixed mode, sharing) >java -version java version "1.5.0_06" Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_06-b05) Java HotSpot(TM) Client VM (build 1.5.0_06-b05, mixed mode, sharing) I will come up with a standalone test and get it to you as soon as possible. Thanks, Cavan
[24 Apr 2008 17:12]
Cavan Morris
Here is the test case and some more info on our platform.
Please fill in the static varibles with the details for your test.
*********Begin Test.java**********
import java.sql.*;
/**
* Created by IntelliJ IDEA.
* User: cmorris
* Date: Apr 24, 2008
* Time: 9:41:21 AM
*/
public class Test {
static String DB_IP = "";
static String DB_NAME = "";
static String DB_USER = "";
static String DB_PASS = "";
static String TABLE_NAME = "";
public static void main(String[] args) {
try {
Class.forName("com.mysql.jdbc.Driver").newInstance();
Connection conn = DriverManager.getConnection("jdbc:mysql://"+DB_IP+"/"+DB_NAME+"?"+"user="+DB_USER+"&password="+DB_PASS);
Statement stmt = conn.createStatement();
stmt.setQueryTimeout(2);
stmt.executeQuery("SELECT * FROM "+TABLE_NAME);
} catch (Exception e) {
e.printStackTrace();
}
}
}
*********End Test.java************
Here is the command I use to run this test:
/usr/java/jdk1.6.0/bin/java -Dfile.encoding=UTF-8 -classpath /usr/java/jdk1.6.0/jre/lib/javaws.jar:/usr/java/jdk1.6.0/jre/lib/jce.jar:/usr/java/jdk1.6.0/jre/lib/charsets.jar:/usr/java/jdk1.6.0/jre/lib/management-agent.jar:/usr/java/jdk1.6.0/jre/lib/jsse.jar:/usr/java/jdk1.6.0/jre/lib/resources.jar:/usr/java/jdk1.6.0/jre/lib/plugin.jar:/usr/java/jdk1.6.0/jre/lib/deploy.jar:/usr/java/jdk1.6.0/jre/lib/rt.jar:/usr/java/jdk1.6.0/jre/lib/ext/sunjce_provider.jar:/usr/java/jdk1.6.0/jre/lib/ext/sunpkcs11.jar:/usr/java/jdk1.6.0/jre/lib/ext/dnsns.jar:/usr/java/jdk1.6.0/jre/lib/ext/localedata.jar:/home/cmorris/testMySQLBug/build/production/testMySQLBug:/home/cmorris/testMySQLBug/lib:/home/cmorris/testMySQLBug/lib/mysql-connector-java-5.1.5-bin.jar Test
The table we are selecting from is an InnoDB table with several million rows. The query shows as 'Writing to net' in a show processlist before the timeout. After the timeout the query disappears. Not knowing anything about the opperation of the driver I'm guessing that the input stream is still waiting for data that will never be sent.
Here are some details on our mysql server installation.
| version | 5.0.45-log
| version_comment | MySQL Community Server (GPL)
| version_compile_machine | x86_64
| version_compile_os | unknown-linux-gnu
Let me know if there is anything else you need.
Cavan
[24 Apr 2008 19:02]
Dave Lennert
Tonci: After further testing, I found this to be a problem in our connection pool management software, not MySQL. Sorry about the confusion. It's working as expected for me.
[29 Apr 2008 7:53]
Tonci Grgin
Dave, can you please elaborate more? It might help Cavan and others facing similar problem.
[29 Apr 2008 16:58]
Dave Lennert
Since Tonci asked, my problem turned out to be in our own software: We have our own connection pool classes. These wrap JDBC Connection's in a layer which (among other things) attempts to intelligently handle exceptions: retrying in some cases, or dissecting vendor-specific exception messages to remap exceptions into more meaningful, vendor-independent exceptions that we define. This layer was naively retrying timeout exceptions, but it inadvertently disabled the timeout during the retry. Thus the effect seen by the ultimate caller was as if the timeout had no effect. I erroneously attributed this to the MySQL JDBC driver. As an aside, I've found cross-vendor handling of JDBC's setQueryTimeout() to be "inconsistent" (to put it mildly). Ranging from a good faith effort all the way to PostgreSQL which concluded that the corner cases were hard and so did nothing (in their latest JDBC driver, setQueryTimeout() always throws an exception). So much for writing portal JDBC clients.
[29 Apr 2008 17:29]
Cavan Morris
We use commons dbcp and I originally suspected a problem there as well. However, the test I uploaded last week does not use any such pooling and the problem persists. Tonci, are you still waiting for more information from me. If my test code does not reproduce the error for you perhaps we can look at differences between your test setup and ours.
[30 Apr 2008 8:43]
Tonci Grgin
Dave, my request to you was out of necessity to create value-add for other. I thank you for posting this analysis as it might help others. Cavan, I was only waiting on your opinion of Dave's analysis, now that you say your problem has nothing to do with that I'll retest.
[8 Jul 2008 6:05]
Ken Johanson
This problem still exists in MySQL-AB JDBC Driver mysql-connector-java-5.1.6 connecting to MySQL 5.0.27. The following code (JSP for convenience) will illustrate the problem after a duration longer than the server's connection timeout.
After the timeout the query hangs indefinitely; instead I believe it should be possible to detect that the connection is invalid by setting the Socket.setSoTimeout(int timeout) parameter (e.g read-timeout) to be equal (or slightly larger) to the Statement.getQueryTimeout()*1000 value. However Statement.setQueryTimeout(int secs) does not result in the throwing of an SQLException (only an indefinate wait).
The server indeed appears not to have correctly closed the connection (netstat show connected); however the driver should still be able to dtect the response timeout (for the incorrect socket shutdown in addition to normal query timeouts)
Tonci or Mark, can you please indicate why this methodology is incorrect, if you believe it to be?
Although an earlier poster attributed this to his pool manager, it STILL is a bug which exists purely in the Mysql product versions I list above. I will provide a fully reproducible test server if requested.
Thank you,
-Ken
<%@page import="java.util.*,java.sql.*" %><pre><%
try {
int TIMEOUT = 5;
String url = "jdbc:mysql://111.111.111.111/dbname?dontTrackOpenResources=true&useTimezone=true&serverTimezone=PST&zeroDateTimeBehavior=convertToNull&characterEncoding=utf-8&user=test&password=*****&connectTimeout=5000&socketTimeout=30000";
Statement st = null;
ResultSet rs = null;
try {
if (con==null)
{
Class.forName("com.mysql.jdbc.Driver").newInstance();
con = DriverManager.getConnection(url,"test", "****");
DatabaseMetaData md = con.getMetaData();
out.println("opened connection...");
out.println(md.getDriverName()+" "+md.getDriverVersion());
out.println(md.getDatabaseProductName()+" "+md.getDatabaseProductVersion());
}
st = con.createStatement();
st.setQueryTimeout(TIMEOUT);
rs = st.executeQuery("SELECT NOW()");
rs.next();
out.println(rs.getString(1));
} catch (Exception e) {
out.println("mysql excepttion: "+e);
} finally {
if (rs!=null)
rs.close();
if (st!=null)
st.close();
}
} catch (Throwable e) {out.println("general exception: "+e);}
%>
<div id="timer"></div>
<script>
var started = new Date().getTime();
function timer() {document.getElementById('timer').innerHTML=new Date().getTime()-started;}
setInterval('timer()',1000);
</script>
<%!
static Connection con;
%>
[31 Jul 2008 19:19]
Tonci Grgin
Guys, I revisited this report and run tests again but still can't reproduce the problem reported... Connected to 5.0.68-pb10-log java.vm.version : 1.5.0_12-b04 --- E Time: 2,281 There was 1 error: 1) testBug31698(testsuite.simple.TestBug31698)java.sql.SQLException: Query execution was interrupted I modified test case so that it looks more like Ken suggested regarding both code and connection string. I also tested with MyISAM and InnoDB engines (same table, same data). So if no one has any new ideas I'd have to close it as configuration specific problem.
[31 Aug 2008 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".
[9 Dec 2008 4:15]
Cavan Morris
I have verified this is fixed in version 5.1.7.
[9 Apr 2009 15:50]
Tonci Grgin
Cavan, good... I was looking and looking finding nothing of interest here and just running in circles.
[6 Jul 2009 23:55]
charles kim
Hi,
It does not seem to timeout if I call a stored procedures like
rs = st.executeQuery("Call testProc()");
Description: After upgrading to mysql-connector-java-5.1.5-bin.jar from mysql-connector-java-5.0.8-bin.jar we found that setting a timeout for a query will kill the query on the server, but it will hang the java thread running the query. No exception is thrown. Here is a stacktrace from a thread that is hung after a query timeout. The threads seem to remain in this state indeffinately. "http-80-Processor24" daemon prio=10 tid=0xb54e0c00 nid=0x4945 runnable [0xb4c14000..0xb4c16130] 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 <0x8d594cc0> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2329) at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1583) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1375) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2697) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:459) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2411) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1657) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2036) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2543) - locked <0x8d595020> (a java.lang.Object) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1737) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1888) - locked <0x8d595020> (a java.lang.Object) How to repeat: Set a short timeout on a long query. Here are the connection url parameters we are using. ?autoReconnect=false&initialTimeout=1&connectTimeout=2000&zeroDateTimeBehavior=convertToNull&jdbcCompliantTruncation=false&useSSL=true Suggested fix: Throw some sort of SQLException on query timeout as per the jdbc documentation.