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:

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

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.

Comments
Aaron Longnion's Gravatar Not sure if this will help, and I didn't test thoroughly yet, but I noticed with SQL Server that if you use SET NOCOUNT ON above your INSERT, then the IdentityCol is not returned in the results struct. Let me know if this helps ;)
# Posted By Aaron Longnion | 1/30/08 9:23 AM
Dan G. Switzer, II's Gravatar @Nathan:

Thanks for this information. This is one of those issues I think is pretty important to bring to people's attention, since it's happening and most people have no idea it's happening.

Anyway, I blogged about it here:
http://blog.pengoworks.com/index.cfm/2008/1/30/Two...
# Posted By Dan G. Switzer, II | 1/30/08 9:45 AM
Nathan Mische's Gravatar @Aaron - I haven't tested this, but adding SET NOCOUNT ON probably triggers the "Auto-generated keys" error, which CF 8 silently ignores. The application I'm working with has 8,000+ queries so making this type of modification really isn't feasible.

@Dan - I think this is very important because you are basically changing the load on your database without changing any code. Most people probably don't even realize this is happening and, depending on your application, this change could have serious consequences.
# Posted By Nathan Mische | 1/30/08 10:39 AM
steve petty's Gravatar got your name from mike petty. im his uncle and am looking for a web maintenance and update and addtions to an existing site. are you interested? please advise me your terms. thanks. steve petty
# Posted By steve petty | 2/26/08 7:16 PM
Kevin Penny's Gravatar @Nathan - I wasn't clear on your 'SET NOCOUNT ON' comment, but I was logging output through the dsn setup in cfadmin 'Log database calls to ' a log file - and saw the generated keys error on a number of queries on our system (we stress starting every with with SET NOCOUNT ON) and for those queries that were throwing silent errors, when I did Add the SET NOCOUNT ON for a query that was INserting into a table - the error DID go away which I think contradicts your statement of "adding set nocount ON probably triggers the 'auto-generated keys' error" - when in fact it removes the error.
# Posted By Kevin Penny | 5/21/09 12:12 PM
Nathan Mische's Gravatar @Kevin - That comment should have read "...adding SET NOCOUNT ON probably _still_ triggers the "Auto-generated keys" error...". Anyway, it is good to know that SET NOCOUNT ON fixes the issue. It is also worth noting that Adobe released a fix for this, so you don't need to go in and change all of your queries: http://kb2.adobe.com/cps/403/kb403432.html
# Posted By Nathan Mische | 5/21/09 12:55 PM
Kevin Penny's Gravatar Well, in my initial testing, on 8.0.1 which is supposed to have this patch already - PLUS using the jvm config arguments, there are still many queries that throw this silent error as documented here:

http://kb2.adobe.com/cps/405/kb405729.html

Their response: basically rewrite the query as separate queries -
# Posted By Kevin Penny | 5/21/09 2:23 PM
Nathan Mische's Gravatar @Kevin - I hadn't seen that tech note so thanks for sharing.
# Posted By Nathan Mische | 5/21/09 4:07 PM
Nathan Mische's Gravatar @Kevin -Quick followup. Are you able to disable auto-generated keys using the -Dcoldfusion.noautogenkeydsns java arg? I can't. I've tired on CF 8,0,1,195765 with and without the hotfix in TechNote kb403432.
# Posted By Nathan Mische | 5/21/09 4:55 PM
Kevin Penny's Gravatar @Nathan -
Nope - same for me - those args do nothing different for me either - and I have the exact same version.
# Posted By Kevin Penny | 5/22/09 10:03 AM
BlogCFC was created by Raymond Camden. This blog is running version 5.8.001.