Problems with CF 8's Generated Keys Feature

So you may have read about CF 8's new ability to return generated keys. For SQL Server 2000 and greater this means that the driver attempts append the SELECT SCOPE_IDENTITY() statement to end of insert statements. If you want to get an idea of how this is done you can take a look at the source for the jTDS JDBC driver. While the jTDS driver isn't what ships with ColdFusion, you can bet that CF's SQL Server driver from DataDirect is doing something similar. In fact you can actually confirm this using SQL Profiler.

Take the following simple test table:

CREATE TABLE TestTable (

    ID int IDENTITY (1, 1) NOT NULL ,

    TestText nvarchar (50) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL

)

Running the following on ColdFusion code:

<cfquery name="testInsert" datasource="scratch_wrapped" result="testResult1">

    INSERT INTO TestTable (TestText)

    VALUES (<cfqueryparam value="This is a test." cfsqltype="cf_sql_varchar">)

</cfquery>

Results in this:

I've pointed out where the "select SCOPE_IDENTITY()" was appended to the prepared statement in the SQL Profiler trace above.

The above example demonstrates a prepared statement, but you can also get automatically generated keys with certain update statements as well. (See this article for some examples.) Now this is a great feature when you need it, but what if you don't? We are in the process of upgrading a fairly large application to CF 8 and this seems to be causing some major issues. Here is what is happening:

Our application runs on three instances of CF 8 Enterprise. After doing extensive functional testing in a test environment we updated the first production server CF 8 and everything seemed to be fine. However, after we upgraded the second server we started to see some database blocking issues. We run SeeFusion and after the upgrade we started to see the following error fill up our JRun logs:

Thinking maybe the issue had something to do with SeeFusion I removed it from the two upgraded servers but we still saw blocking. In fact we actually had a client/server distributed deadlock which brought down our production site for a few minutes. At this point I still wasn't sure what was causing the issue but my boss pointed out that since upgrading we were seeing about 3 times the amount of network traffic going into and out of our database server. This combined with the error message from SeeFusion led me to take a closer look at the changes to cfquery and ColdFuison JDBC drivers.

I did some experimenting and, from what I can tell, ColdFusion tries to return generated keys whether or not you have specified a result attribute for your cfquery tag.

Take, for example, the following query where I add the SELECT SCOPE_IDENTITY() statement and don't specify a result attribute:

<cfquery name="testInsert" datasource="scratch_wrapped">

    INSERT INTO TestTable (TestText)

    VALUES ('This is a test.')

    SELECT SCOPE_IDENTITY()

</cfquery>

This causes SeeFusion to log the following to the cfusion-out.log file:

2008-01-28 13:18:50 SeeFusion: ----Statement[12]:  exception start ----

2008-01-28 13:18:50 SeeFusion: java.sql.SQLException: [Macromedia][SQLServer JDBC Driver]Auto-generated keys were not requested, or the SQL was not a simple INSERT statement.

    at macromedia.jdbc.base.BaseExceptions.createException(Unknown Source)

    at macromedia.jdbc.base.BaseExceptions.getException(Unknown Source)

    at macromedia.jdbc.base.BaseStatement.getGeneratedKeys(Unknown Source)

    at com.seefusion.zd.getGeneratedKeys(zd.java:546)

    at coldfusion.server.j2ee.sql.JRunStatement.getGeneratedKeys(JRunStatement.java:415)

    at coldfusion.sql.Executive.getRowSet(Executive.java:487)

    at coldfusion.sql.Executive.executeQuery(Executive.java:1205)

    at coldfusion.sql.Executive.executeQuery(Executive.java:1008)

    at coldfusion.sql.Executive.executeQuery(Executive.java:939)

    at coldfusion.sql.SqlImpl.execute(SqlImpl.java:325)

    at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:831)

    at coldfusion.tagext.sql.QueryTag.doEndTag(QueryTag.java:521)

    at cfscribble2ecfm900752232.runPage(C:\var\cfmxapp\dev.nmische.cdicorp.com\scribble.cfm:1)

    at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:192)

    at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:366)

    at coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65)

    at coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:279)

    at coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:48)

    at coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40)

    at coldfusion.filter.PathFilter.invoke(PathFilter.java:86)

    at coldfusion.filter.LicenseFilter.invoke(LicenseFilter.java:27)

    at coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:70)

    at coldfusion.filter.BrowserDebugFilter.invoke(BrowserDebugFilter.java:74)

    at coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:28)

    at coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38)

    at coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:46)

    at coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38)

    at coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22)

    at coldfusion.CfmServlet.service(CfmServlet.java:175)

    at coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)

    at jrun.servlet.FilterChain.doFilter(FilterChain.java:86)

    at coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:42)

    at coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46)

    at jrun.servlet.FilterChain.doFilter(FilterChain.java:94)

    at com.seefusion.Filter.doFilter(Filter.java:49)

    at com.seefusion.SeeFusion.doFilter(SeeFusion.java:1500)

    at jrun.servlet.FilterChain.doFilter(FilterChain.java:94)

    at jrun.servlet.FilterChain.service(FilterChain.java:101)

    at jrun.servlet.ServletInvoker.invoke(ServletInvoker.java:106)

    at jrun.servlet.JRunInvokerChain.invokeNext(JRunInvokerChain.java:42)

    at jrun.servlet.JRunRequestDispatcher.invoke(JRunRequestDispatcher.java:284)

    at jrun.servlet.ServletEngineService.dispatch(ServletEngineService.java:543)

    at jrun.servlet.jrpp.JRunProxyService.invokeRunnable(JRunProxyService.java:203)

    at jrunx.scheduler.ThreadPool$ThreadThrottle.invokeRunnable(ThreadPool.java:428)

    at jrunx.scheduler.WorkerThread.run(WorkerThread.java:66)



2008-01-28 13:18:50 SeeFusion: ----Statement[12]:  exception end ----

If you notice, there is a call to coldfusion.server.j2ee.sql.JRunStatement.getGeneratedKeys(). This query is not a simple insert so this error is thrown and silently handled by ColdFusion. Judging by the number of similar "Auto-generated keys" errors in my cfusion-out.log there appear to be quite a few query conditions that can throw this error.

As for the the issue we are seeing, our application does a lot of logging so it runs several simple inserts for every page request. Some of these use cfqueryparam and some do not. My best guess is that the added overhead of appending SELECT SCOPE_IDENTITY() to some of those logging queries, along with overhead of throwing and silently handling the "Auto-generated keys" error above is slowing things down enough that we are seeing these SQL Server blocking issues. I'd love to be able to disable the autoGeneratedKeys behavior in CF 8 to confirm this, but so far I haven't been able to figure out how. If anyone knows please let me know.

The good news is the blocking issue does not seem to be related to SeeFusion; SeeFusion was simply relaying an error message that CF 8 ignores. As reported by Dan G. Switzer, II, there is a fix for this. So if you find that your version of SeeFusion is reporting these errors be sure to update to the latest and greatest, which as of this writing is 4.0.7. (And thanks to the Webapper team for answering my SeeFusion questions and getting this new build to me last week!)

Also, I'm not sure if this would be considered a ColdFusion bug or not, but we have opened a ticket with Adobe to see what we can figure out. I'll be sure to post a follow up as I learn more.