querytimeout doesn't work for load-balanced and fail-over urls
Posted by: murat cengiz
Date: January 16, 2013 07:33AM

Hi,

Setting queryTimeout() seems to have no effect when using loadbalanced url.

I am using a query that takes more than 5s to execute with the following code:

Connection conn = DriverManager.getConnection(url);
PreparedStatement ps = conn.prepareStatement(aLongRunningSql);
ps.setQueryTimeout(2);
ResultSet rs = ps.executeQuery();

Using:
java 1.6
connector/j 5.1.22
url : jdbc:mysql:loadbalance://host1,host2:3306/test?connectTimeout=3000&socketTimeout=5000

The following exception is caught after socketTimeout ms, and at that point the connection starts to point to host2:

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 5,102 milliseconds ago. The last packet sent successfully to the server was 5,006 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3589)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:156)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.executeSql(ConnectorJSocketTimeoutTest.java:73)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.run(ConnectorJSocketTimeoutTest.java:47)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.main(ConnectorJSocketTimeoutTest.java:97)
Caused by: 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:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)
... 11 more
error info : sql state=08S01 error code=0 type=com.mysql.jdbc.exceptions.jdbc4.CommunicationsException cause=java.net.SocketTimeoutException: Read timed out

Looking at the thread dump (somewhere after 2s and before 5s after issuing the query):

"Thread-1" daemon prio=10 tid=0x00007f9308001000 nid=0x30eb waiting for monitor entry [0x00007f9351a73000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mysql.jdbc.LoadBalancedMySQLConnection.getActiveMySQLConnection(LoadBalancedMySQLConnection.java:51)
- waiting to lock <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.mysql.jdbc.LoadBalancedMySQLConnection.getQueryTimeoutKillsConnection(LoadBalancedMySQLConnection.java:592)
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:107)

"MySQL Statement Cancellation Timer" daemon prio=10 tid=0x00007f935c844000 nid=0x30d1 in Object.wait() [0x00007f9351b74000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d74db358> (a java.util.TaskQueue)
at java.lang.Object.wait(Object.java:485)
at java.util.TimerThread.mainLoop(Timer.java:483)
- locked <0x00000007d74db358> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)

"Abandoned connection cleanup thread" daemon prio=10 tid=0x00007f935c0e5800 nid=0x30d0 in Object.wait() [0x00007f935206f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d6b04278> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00000007d6b04278> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)

"main" prio=10 tid=0x00007f935c00e800 nid=0x30b5 runnable [0x00007f9362121000]
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:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x00000007d71979a0> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
- locked <0x00000007d701c998> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:156)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
- locked <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
- locked <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.executeSql(ConnectorJSocketTimeoutTest.java:73)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.run(ConnectorJSocketTimeoutTest.java:47)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.main(ConnectorJSocketTimeoutTest.java:97)

The querytimeout thread ("Thread-1") has actually started, but was waiting to lock <0x00000007d6ee4760>, which is already locked by "main" thread issuing the query. But at the time it acquires the lock, it probably is too late.

I have also tried with a fail-over url and got similar results.

I should note that everything works as expected when using a basic url, i.e. jdbc:mysql://host1:3306/test?connectTimeout=3000&socketTimeout=5000

After 2 seconds it fails with :
com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2841)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.executeSql(ConnectorJSocketTimeoutTest.java:73)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.run(ConnectorJSocketTimeoutTest.java:47)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.main(ConnectorJSocketTimeoutTest.java:97)
error info: sql state=null error code=0 type=com.mysql.jdbc.exceptions.MySQLTimeoutException cause=null

Any comments?

thanks

Options: ReplyQuote


Subject
Written By
Posted
querytimeout doesn't work for load-balanced and fail-over urls
January 16, 2013 07:33AM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.