CFQuery Timeout Uses KILL QUERY Command With MySQL 5 Driver In ColdFusion
I am always delighted to learn new things about ColdFusion since I've been using it for the better part of two decades. Case in point, the other day, fellow InVision engineer Shawn Grigson showed me that the CFQuery tag has a "timeout" attribute. Having never seen this before, I thought it would be fun to try and poke at it for a bit and see how it works; at least in the context of the MySQL 5 Driver (assuming that the behavior may vary from driver to driver). And, from what I can tell, ColdFusion uses the KILL QUERY command to try and terminate long-running queries.
To investigate the behavior, I wanted to try and run a multi-statement query that would timeout mid-execution. Then, I figured I could look at the General Log to see which of the statements were executed and which were skipped:
<!---
First, let's enable and clear the GENERAL LOG so we can see what queries actually
execute in the MySQL database server.
--->
<cfquery name="setup">
SET GLOBAL general_log = 'ON';
SET GLOBAL log_output = 'TABLE';
TRUNCATE TABLE
mysql.general_log
;
TRUNCATE TABLE
timeout_test
;
</cfquery>
<cftry>
<!---
Now, let's run a query that we KNOW will run longer that the applied timeout
since it has SLEEP commands mixed-in with it. This will throw a Database error
of type, "Database". In order for this exploration to work, our data-source has
to have multi-statements enabled.
--->
<cfquery timeout="3">
INSERT INTO timeout_test SET value = 10;
SELECT SLEEP( 2.1 );
INSERT INTO timeout_test SET value = 20;
<!--- We expect the CFQUERY tag to timeout during this SLEEP. --->
SELECT SLEEP( 2.2 );
<!--- We expect the CFQUERY tag to timeout during this SLEEP. --->
INSERT INTO timeout_test SET value = 30;
SELECT SLEEP( 20 );
INSERT INTO timeout_test SET value = 40;
</cfquery>
<cfcatch>
<cfdump
var="#cfcatch#"
label="Query Error"
show="type,message,detail"
/>
</cfcatch>
</cftry>
<!---
As you will see, it turns out that we don't actually need to sleep here since the
series of queries continues to execute after the KILL QUERY command (since only
currently-executing statement is killed).
<cfset sleep( 30 * 1000 ) />
--->
<!--- Let's see which test values were actually inserted. --->
<cfquery name="test">
SELECT
id,
value
FROM
timeout_test
</cfquery>
<!--- Let's see which query statements were actually executed. --->
<cfquery name="log">
SELECT
CONVERT( l.argument USING utf8 ) AS argument
FROM
mysql.general_log l
WHERE
l.argument NOT LIKE '%general_log%' -- That's THIS query.
AND
l.argument NOT LIKE '%PROCESSLIST%' -- That's me looking at the processlist.
ORDER BY
l.event_time ASC
</cfquery>
<cfdump var="#test#" label="Test Values" />
<cfdump var="#log#" label="MySQL General Log" />
As you can see, I have a single, multi-statement query that interweaves INSERT statements with SLEEP statements. The timeout for the query is only 3-seconds; but, the SLEEP statements account for over 20-seconds, which guarantees that our error will be thrown. After that, I look to both the General Log and the test values to help deduce the underlying behavior.
And, when we run the above code, we get the following page output:
This is very interesting stuff! What we can see from the General Log is that, at the threshold of the timeout, ColdFusion actually establishes a new connection to the database and issues a KILL QUERY command for the currently-executing statement. But, this doesn't kill the overall query - just the current statement. As such, the rest of the statements, including the SLEEP(20), are allowed to execute. This is recorded in the General Log; but, we can also divine this behavior from the test values, all of which were inserted into the test table.
Looking at the network activity for the page, we can also see that it took over 20-seconds for the page to render. This means that even though the CFQuery timed-out at 3-seconds, it continued to block while the rest of the statements in the CFQuery body executed (before ColdFusion finally threw the Database error).
Another interesting fact that we may be able to deduce from this is that if the connection pool is exhausted, ColdFusion may be unable to make the subsequent connection it needs in order to issue the KILL QUERY command. As such, if the database starts to hang, I wouldn't be surprised if the Timeout attribute essentially stopped working. Of course, more testing with a constrained connection pool would be need in order to know for sure.
At work, we started experimenting with the Timeout attribute on "hot queries" that were called with very high volume as these queries were the first to explode if the database slowed down. So far, I don't have enough of a mental model to know if this is helping. But, it's nice to know that the CFQuery does have a Timeout attribute.
Want to use code from this post? Check out the license.
Reader Comments
Hey Ben, though I've known about the query timeout attribute for years, I didn't know about this KILL behavior. Thanks for enlightening me! So, what version of ColdFusion are you running?
@Aaron,
I'm afraid to answer :D ... we're still running CF 10 in production. Though, I'm thinking of upgrading my blog so at least I have a chance to stay current.
@ben - You're not the only one ;-) But we're close to finalizing the upgrade to 2016!
Thanks for all your super helpful blogging!
I did not know it issued the Kill command very interesting. If you look up Kill Query it basically states it only Kills the statement not the connection. KILL QUERY terminates the statement the connection is currently executing, but leaves the connection itself intact. If they called KILL Connection that most likely would blow away all the statements.
That is "interesting" but I'm not sure the behavior you describe for multi-statement CFQUERY's really makes much sense. A more logical (at least to my tiny brain) would be for the CFQUERY as a whole to be "timed out" (aborted?) rather than just the currently-executing statement. The behavior then would be consistent across single- and multi-statement CFQUERY's. It would be interesting to play with that behavior across drivers and DBMS's to see if the behavior is consistent. Years ago, we played with the timeout attribute a bit with SQL Server on the backend in working on a simple server health check and came away feeling like it wasn't doing what it was supposed to. I may pick that up again out of curiosity if I get a spare bit of time.
@All,
I did a quick follow-up to see what would happen if this was done while using a Connection Pool that was limited to size One:
www.bennadel.com/blog/3306-coldfusion-does-not-appear-to-use-the-connection-pool-when-issuing-kill-query-commands.htm
... it seems that ColdFusion does not use the Connection Pool when issuing the KILL QUERY commands; but, rather, a unique one-off connection is established.
@Mike, @Ron,
It is definitely a curious situations. As I only just came upon this feature, I am not sure what I would expect the behavior to be. I will say that, by default, MySQL doesn't allow multi-statement queries - you have to specifically enable it in the connection string. So, if you're using a single-statement query, the Timeout should kind of work as expected. But, with a multi-statement.... hmm, it is interesting.
I suppose if you're wrapping this in a Transaction [I'm guessing] that the entire thing would be rolled back if any one of the statements was interrupted.