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.