6

We have a problem, we are calling SQL Server 2005 from ColdFusion 9. I can't post the original query but it isn't the focus of the problem, I have posted the relevant combo of things causing the problem.

We have a query that is a much more complicated version of the following example query, where the something column is a primary key. The value parameter isn't changing. This query, for some bizarre reason that we can't understand, takes almost 20 seconds to run....

<cfquery result="q" datasource="dsn">
  SELECT something
  FROM somewhere
  WHERE something = <cfqueryparam cfsqltype="cf_sql_integer" value="#value#"/> 
</cfquery>

Notice if you, highlight the last line of source code above, there is a space after the cfqueryparam tag.

The following query, completely different as I am sure you can see for yourself, takes 15 ms to run.

<cfquery result="q" datasource="dsn">
  SELECT something
  FROM somewhere
  WHERE something = <cfqueryparam cfsqltype="cf_sql_integer" value="#value#"/>
</cfquery>

There are no spaces after the cfqueryparam. However, adding two spaces at the end gives 15 ms as well. If we then go back to one space at the end gives us the result in about 20 seconds again.

We've examined the DB driver logs between Java and SQL Server and nothing seems out of the ordinary. What could be happening here?

Edit

We have run profiling on the SQL Server and it shows that for the query with the single space it is using a different cached execution plan from the one with zero or multiple spaces. SQL Server caches the execution plans for the queries. It also uses the full literal query as the identifier. So when we were sending the other queries a different execution plan is being used.

Further

One of the execution plans looks like it is looking up on an incorrect index on one of the sub selects, it's not clear why SQL Server has decided on this alternate execution plan or why it appears that one of the indexes is wrong.

Follow up

For anyone interested in what might have caused the bad execution plan, the follow up question was posted here: SQL Server 2005 cached an execution plan that could never work

Community
  • 1
  • 1
Stuart Wakefield
  • 6,294
  • 24
  • 35
  • 3
    It's not clear from your explanation if the execution time is on the SQL Server side or the app server side (or maybe that's part of your question!). Have you watched this happen through SQL Profiler? Are there differences seen through Profiler between the two? – squillman Jan 09 '13 at 16:59
  • 1
    If you run the first query twice, is it still slow the second time? If not, then the slowness might be caused by compiling and developing an execution plan. – Dan Bracuk Jan 09 '13 at 17:06
  • 1
    It seems to be that SQL Server is caching a slow execution plan, I will update my question. – Stuart Wakefield Jan 09 '13 at 17:13
  • is the , after 'something' in the first query a type-o? – genericHCU Jan 09 '13 at 17:39
  • does the first query have a result attribute? I've seen result="something" slow a query way down for no reason. – genericHCU Jan 09 '13 at 17:42
  • Yes (edited) and yes but it would appear that the problem is more the SQL Server end of things, not sure why it is using different execution plans... Will report the differences – Stuart Wakefield Jan 09 '13 at 17:54
  • 1
    just curious, try running the slow query without the result attribute – genericHCU Jan 09 '13 at 18:12
  • 1
    also, have you seen this post that points out varchar vs nvarchar and how it may not use the index? (i'm assuming you have more in your "complex" query that you're not showing us that could be effected by this post) http://stackoverflow.com/questions/10543755/slow-query-with-cfqueryparam-searching-on-indexed-column-containing-hashes – genericHCU Jan 09 '13 at 18:18
  • Changing the result attribute made no difference and both times the parameter is being passed as an integer. I think Adam's post explains what we are seeing and as I can't post the details of the queries, indexes, relations and execution plans I think the rest is down to us. I'll update if anything useful comes out of it that might benefit someone else. – Stuart Wakefield Jan 10 '13 at 10:09

1 Answers1

4

This is possibly a symptom of something that cropped up on the Railo forums the other day (weird coincidence).

There's a chance that the nature of the parameter value used when the slow version of the query was first run caused an execution plan to be created which was "convenient" for that specific value, but for more typical subsequent values, the plan was less than ideal. Conversely when the second query was first run, the value passed as the parameter was more typical of how the query is called, so the execution plan is a better fit for most other values.

I've not personally seen this happen, but I have read about it enough times. And it does sound like what you're seeing.

If possible, test this out by clearly the SQL Server cache, then re-run the queries with the value that caused the "bad" plan to be compiled, and you should see similar behaviour.

This is not a solution, but it'll demonstrate that it might be the cause, and allow you to address what might be the underlying cause of the discrepancies in plans for different values.

This experimentation is obviously predicated on knowing what the param values were at the time the queries were first called, which is... well it'd be fortuitous for you if you did know them.

Leigh
  • 28,765
  • 10
  • 55
  • 103
Adam Cameron
  • 29,677
  • 4
  • 37
  • 78
  • Thanks again Adam! This seems to be exactly what we are seeing. We'll try to track down the original query or replicate it to find out why the bad plan was used... If anything interesting comes out of that I'll update. – Stuart Wakefield Jan 10 '13 at 09:57