Bug #25836 Query execution which timed out not always throws MySQLTimeoutException
Submitted: 24 Jan 2007 17:19 Modified: 22 Feb 2007 14:19
Reporter: Damián Arregui Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:5.0.4 OS:
Assigned to: CPU Architecture:Any

[24 Jan 2007 17:19] Damián Arregui
Description:
Consider a JDBC statement and a query execution method such as Statement.executeUpdate(). If we associate a timeout to the statement via Statement.setQueryTimeout() and if the query execution does time out, Statement.executeUpdate() should throw a MySQLTimeoutException. This is not always the case.

The problem comes from a race condition between the client thread calling Statement.executeUpdate() and the anonymous "cancel thread" in CancelTask.run().

The "cancel thread" successfully executes line 104 of Statement.java:

cancelStmt.execute("KILL QUERY " + connectionId);

This unblocks the client thread in Statement.executeUpdate(), which goes through the following code:

if (this.wasCancelled) {
    this.wasCancelled = false;
    throw new MySQLTimeoutException();
}

But since the value of wasCancelled is false, it does not throw an exception.

Only then, the "cancel thread" executes line 105 of Statement.java:

wasCancelled = true;

But it's too late!

How to repeat:
Use a Java debugger. Put a break point at line 105 of Statement.java.

Create a statement and set a timeout so that the timeout will be reached.

Execute the statement.

The statement will be cancelled via "KILL QUERY" but the client will not get any exception.

Suggested fix:
Once a statement is being cancelled, its execution should not return before the outcome of the cancel operation is known.
[5 Feb 2007 11:55] Tonci Grgin
Hi Damián and thanks for your report. 

I can agree with you on race condition but I'm not sure how this should be treated since on subsequent access to canceled statement you will get "Query execution was interrupted" which is descriptive enough. However, I'll set this to "Verified" so that others may take a look.

Extract from general query log (dnevnik is just a rather large table)
070205 12:24:42	     10 Connect     root@localhost on solusd
		     10 Query       SHOW VARIABLES
		     10 Query       SHOW COLLATION
		     10 Query       SET character_set_results = NULL
		     10 Query       SET autocommit=1
		     10 Query       SET sql_mode='STRICT_TRANS_TABLES'
		     10 Query       SELECT VERSION()
		     10 Query       Select * FROM dnevnik
070205 12:24:47	     11 Connect     root@localhost on solusd
		     11 Query       SHOW VARIABLES
		     11 Query       SHOW COLLATION
		     11 Query       SET character_set_results = NULL
		     11 Query       SET autocommit=1
		     11 Query       SET sql_mode='STRICT_TRANS_TABLES'
		     11 Query       KILL QUERY 10
		     11 Quit       
070205 12:27:44	     10 Quit
[5 Feb 2007 18:45] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/19333
[22 Feb 2007 14:19] MC Brown
A note has been added to the 5.0.5 changelog.