Performance issues with <cfqueryparam /> on first execution when using Microsoft SQL Server

Let's say we have the following query in ColdFusion. We'll call this "Method 1":

select
  Name, Email, Phone
from
  Employee
where
  DepartmentId = <cfqueryparam cfsqltype="cf_sql_integer" value="1" />

When you use the <cfqueryparam /> tag, ColdFusion translates the code into a bound parameter. This has the benefit of helping prevent SQL injections, but it often helps with performance because it allows the backend database (like Microsoft SQL Server) to cache the execution plan—which can help speed up performance. So roughly speaking, when the following query is executed on the server, it's translated to (which we'll call "Method 2":)

declare @p1 int
set @p1 = 1

select
  Name, Email, Phone
from
  Employee
where
  DepartmentId = @p1

You'll see this if you turn on ColdFusion debugging, and you can verify that even the name @p1 is used if you try manually adding a declare @p1 statement to your ColdFusion query.

However, when I'd run the bound version of my query in Microsoft SQL Server Management Studio, I was seeing dramatically different results. With a cleared cache, the "Method 1" query was running 7 times slower than "Method 2" when I'd run it in a query analyzer window. In the process of trying to troubleshoot the problem, I tried running the following in my ColdFusion query (which we'll call "Method 3":)

declare @p1 int
set @p1 = <cfqueryparam cfsqltype="cf_sql_integer" value="1" />

select
  Name, Email, Phone
from
  Employee
where
  DepartmentId = @p1

What's interesting about "Method 3" is I was now seeing the exact same performance as I was seeing when I run "Method 2" from my desktop locally. This had my confused and I knew I had to be missing something. I was obviously missing a key execution step that was missing between "Method 1" and "Method 2". What's even more confusing is that I had already been running SQL Profiler on the database server to catch the TSQL statements being executed—it's how I originally captured the query I was using in "Method  2" to run locally. The problem was I was missing a key event that I should have been logging—the RPC:Starting and RPC:Completed events.

Once I enabled the RPC:Starting event, I saw where the bottleneck was coming through.

When you use <cfqueryparam /> in SQL Server, the query isn't just translated directly into a bound statement, but instead it's first passed into the sp_prepexec system stored procedure.  So, instead of actually executing "Method 2" immediately, something like the following executed first:

declare @p1 int
set @p1=68
exec sp_prepexec @p1 output,N'@P1 int',N'select
  Name, Email, Phone
from
  Employee
where
  DepartmentId = @p1',190
select @p1

It was the call to the sp_prepexec stored procedure that was causing the huge difference in performance between "Method 1" and "Method 2". It turns out it was taking this stored procedure a lot of time to figure out the best execution plan to use before it could cache it.

To fix the problem, I just spent some time with my query (which actually ended up involving modifying some core system views) so that sp_prepexec could analyze my query and returned the cached plan faster.

So, if you're having performance issues—especially on first run execution—you might want to monitor your server and see if the bottleneck isn't with the sp_prepexec trying to figure out the best plan to cache.