The last couple of weeks have been interesting for me. I spent a bulk of the time tuning queries to optimize for performance and a learned a number of interesting things about Microsoft SQL Server and where some of the bottlenecks in our application actually lie.
One interesting situations I ran into was that I wasn't able to replicate some of the performance issues I was seeing in our application when I'd run the same query from Query Analyzer. Now there's a number of reasons why this could happen, but in my case I thought I was running the query in manner that mimicked what was being executed on the server—but it turns out I was missing a key step in the process and I'll get to that in a minute.
So, what was the problem? Let me explain.
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.