Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

We are using SQL Server 2008 R2, and have a very large (100M+ rows) table with a primary id index, and a datetime column with a nonclustered index. We are seeing some highly unusual client/server behavior based upon the use of an order by clause specifically on a indexed datetime column.

I read through the following post: http://stackoverflow.com/questions/1716798/sql-server-2008-ordering-by-datetime-is-too-slow but there is more going on with the client/server than what is begin described here.

If we run the following query (edited to protect some content):

select * 
from [big table] 
where serial_number = [some number] 
order by test_date desc

The query times-out every time. In the SQL Server Profiler the executed query looks like this to the server:

exec sp_cursorprepexec @p1 output,@p2 output,NULL,N'select * .....

Now if you modify the query to, say this:

declare @temp int;
select * from [big table] 
where serial_number = [some number] 
order by test_date desc

The the SQL Server Profiler shows the executed query looks like this to the server, and it WORKS instantly:

exec sp_prepexec @p1 output, NULL, N'declare @temp int;select * from .....

As a matter of fact, you can even put an empty comment ('--;') instead of a unused declare statement and get the same result. So initially we were pointing to the sp pre-processor as the root cause of this issue, but if you do this:

select * 
from [big table] 
where serial_number = [some number] 
order by Cast(test_date as smalldatetime) desc

It works instantly as well (you can cast it as any other datetime type), returning the result in milliseconds. And the profiler shows the request to the server as:

exec sp_cursorprepexec @p1 output, @p2 output, NULL, N'select * from .....

So that somewhat excludes the sp_cursorprepexec procedure from the full cause of the issue. Add to this the fact that the sp_cursorprepexec is also called when no 'order by' is used and the result it also returned instantly.

We've googled around for this issue quite a bit, and I see similar issues posted from others, but none that break it down to this level.

So have others witnessed this behavior? Does anyone have a solution better than putting meaningless SQL in front of the select statement to change the behavior? Being that SQL Server should be invoking the order by after the data is collected, it sure seems like this is a bug in the server that has persisted for a long time. We have found this behavior to be consistent across many of our large tables, and is reproducible.

Edits:

I should also add putting a forceseek in also makes the problem disappear.

I should add to help the searchers, the ODBC timeout error thrown is: [Microsoft][ODBC SQL Server Driver]Operation canceled

Added 10/12/2012: Still hunting down root cause, (along with having built a sample to give to Microsoft, I will cross post any results here after I submit). I have been digging into the ODBC trace file between a working query (with an added comment/declare statement) and non-working query. The fundamental trace difference is posted below. It occurs on the call to SQLExtendedFetch call after all of the SQLBindCol discussions are completed. The call fails with return code -1, and the parent thread then enters SQLCancel. Since we are able to produce this with both the Native Client and Legacy ODBC drivers, I'm still pointing to some compatibility issue on the server side.

(clip)
MSSQLODBCTester 1664-1718   EXIT  SQLBindCol  with return code 0 (SQL_SUCCESS)
        HSTMT               0x001EEA10
        UWORD                       16 
        SWORD                        1 <SQL_C_CHAR>
        PTR                0x03259030
        SQLLEN                    51
        SQLLEN *            0x0326B820 (0)

MSSQLODBCTester 1664-1718   ENTER SQLExtendedFetch 
        HSTMT               0x001EEA10
        UWORD                        1 <SQL_FETCH_NEXT>
        SQLLEN                     1
        SQLULEN *           0x032677C4
        UWORD *             0x032679B0

MSSQLODBCTester 1664-1fd0   ENTER SQLCancel 
        HSTMT               0x001EEA10

MSSQLODBCTester 1664-1718   EXIT  SQLExtendedFetch  with return code -1 (SQL_ERROR)
        HSTMT               0x001EEA10
        UWORD                        1 <SQL_FETCH_NEXT>
        SQLLEN                     1
        SQLULEN *           0x032677C4
        UWORD *             0x032679B0

        DIAG [S1008] [Microsoft][ODBC SQL Server Driver]Operation canceled (0) 

MSSQLODBCTester 1664-1fd0   EXIT  SQLCancel  with return code 0 (SQL_SUCCESS)
        HSTMT               0x001EEA10

MSSQLODBCTester 1664-1718   ENTER SQLErrorW 
        HENV                0x001E7238
        HDBC                0x001E7B30
        HSTMT               0x001EEA10
        WCHAR *             0x08BFFC5C
        SDWORD *            0x08BFFF08
        WCHAR *             0x08BFF85C 
        SWORD                      511 
        SWORD *             0x08BFFEE6

MSSQLODBCTester 1664-1718   EXIT  SQLErrorW  with return code 0 (SQL_SUCCESS)
        HENV                0x001E7238
        HDBC                0x001E7B30
        HSTMT               0x001EEA10
        WCHAR *             0x08BFFC5C [       5] "S1008"
        SDWORD *            0x08BFFF08 (0)
        WCHAR *             0x08BFF85C [      53] "[Microsoft][ODBC SQL Server Driver]Operation canceled"
        SWORD                      511 
        SWORD *             0x08BFFEE6 (53)

MSSQLODBCTester 1664-1718   ENTER SQLErrorW 
        HENV                0x001E7238
        HDBC                0x001E7B30
        HSTMT               0x001EEA10
        WCHAR *             0x08BFFC5C
        SDWORD *            0x08BFFF08
        WCHAR *             0x08BFF85C 
        SWORD                      511 
        SWORD *             0x08BFFEE6

MSSQLODBCTester 1664-1718   EXIT  SQLErrorW  with return code 100 (SQL_NO_DATA_FOUND)
        HENV                0x001E7238
        HDBC                0x001E7B30
        HSTMT               0x001EEA10
        WCHAR *             0x08BFFC5C
        SDWORD *            0x08BFFF08
        WCHAR *             0x08BFF85C 
        SWORD                      511 
        SWORD *             0x08BFFEE6
(clip)

Added a Microsoft Connect case 10/12/2012:

https://connect.microsoft.com/SQLServer/feedback/details/767196/order-by-datetime-in-odbc-fails-for-clean-sql-statements#details

I should also note that we did look up the query plans for both the functioning, and non-functioning queries. They are both reused appropriately based upon the execution count. Flushing the cached plans and re-running does not change the success of the query.

share|improve this question

migrated from stackoverflow.com Oct 10 '12 at 17:14

This question came from our site for professional and enthusiast programmers.

    
What happens if you try select id, test_date from [big table] where serial_number = ..... order by test_date - I'm just wondering if the SELECT * has a negative impact on your performance. If you have a nonclustered index on test_date and a clustered index on id (assuming that's what it's called), this query should be covered by that nonclustered index and thus should return quite quickly –  marc_s Oct 10 '12 at 16:45
    
Sorry, good point. I should have included that we tried modifying the selected column space (removing the '*', etc) heavily with various combinations. The behavior described above persisted through those changes. –  DBtheDBA Oct 10 '12 at 16:48
    
I've linked my accounts now to that site. If a moderator wants to move the post to that site, I'm fine either way. One of my developers pointed that site out to me after I posted here. –  DBtheDBA Oct 10 '12 at 17:05
    
Which client stack is being used here? Without the entire trace text, that seems like the issue. Try wrapping the original call inside sp_executesql and see what happens. –  Jon Seigel Oct 10 '12 at 17:25
1  
What does the slow execution plan look like? Parameter sniffing? –  Martin Smith Oct 10 '12 at 17:42
show 7 more comments

3 Answers 3

There's no mystery, you get a good(er) or (really) bad plan at basically random because there is no clear cut choice for the index to use. While compelling for the ORDER BY clause and thus avoid the sort, you non-clustered index on the datetime column is a very poor choice for this query. What would make a much better index for this query would be one on (serial_number, test_date). Even better, this would make a very good candidate for a clustered index key.

As a rule of thumb time series should be clustered by the time column, because the overwhelming majority of requests are interested in specific time ranges. If the data is also inherently partitioned on a column with low selectivity, like it seems to be the case with your serial_number, then this column should be added as the leftmost one in the clustered key definition.

share|improve this answer
    
I'm a bit confused here. Why would the plan be based upon the order by clause? Shouldn't the plan limit itself to the where conditions as the ordering should only occur after the rows have been fetched? Why would the server try and sort the records prior to having the entire result set? –  DBtheDBA Oct 10 '12 at 18:47
3  
This also doesn't explain why adding a comment at the beginning of the query affects the run duration. –  cfradenburg Oct 10 '12 at 19:14
    
Also, our tables are almost always queried by serial number, not test_date. We have non-clustered indexes on both, and a clustered only on the id column in the table. It's an operational data store, and adding clustered indexes on other columns would only drive page splits and poorer performance. –  DBtheDBA Oct 10 '12 at 21:49
1  
@DBtheDBA: if you want to make a claim for a 'bug' you need to do a proper investigation and disclosure. The exact schema of your table and exported stats, follow How to generate a script of the necessary database metadata to create a statistics-only database in SQL Server 2005 and in SQL Server 2008, specifically the all important Script Statistics: Script Statistics and histograms. Add these to the post info along with steps that reproduce the issue. –  Remus Rusanu Oct 11 '12 at 6:05
1  
We read that before during our searches, and I understand what you are saying, but there is a fundamental flaw in something the server is doing here. We've rebuilt the table, and the indexes, and have reproduced it on a new table. The recompile option doesn't fix the issue, which is a big hint something is wrong. I don't doubt that putting clustered indexes on everything could potentially fix this problem, but its not a solution to the root cause, it's a workaround, and an expensive one on a large table. –  DBtheDBA Oct 11 '12 at 15:42
show 5 more comments

Document the details of how to reproduce the bug and submit it on connect.microsoft.com. I checked and couldn't see anything out there already that would be related to this.

share|improve this answer
    
I'll get my DBA to type up a script tomorrow to create an environment to reproduce. I don't think it's that difficult. I'll post it here as well should someone be interested in trying it themselves. –  DBtheDBA Oct 10 '12 at 20:37
    
Post the connect item too when it gets opened. That way if someone else has this issue they get pointed right to it. And anyone watching this question may want to vote the item up so Microsoft is more likely to pay attention to it. –  cfradenburg Oct 11 '12 at 11:30
add comment

My hypothesis is that you are running afoul of the query plan cache. (Remus might be saying the same thing as I am, but in a different way.)

Here is a ton of detail on how SQL does plan caching.

Glossing over the details: Someone ran that query earlier, for a particular [some number]. SQL looked at the value provided, the indexes and statistics for the relevant table/columns, etc. and built a plan that worked well for that particular [some number]. It then cached the plan, ran it and gave the results back to the caller.

Later, someone else is running the same query, for a different value of [some number]. This particular value results in a wildly different number of result rows and the engine should create a different plan for this instance of the query. But it doesn't work that way. Instead, SQL takes the query and (more or less) does a case-sensitive search of the query cache, looking for a pre-existing version of the query. When it finds the one from earlier, it just uses that plan.

The idea is that it saves on the time required to decide on the plan and build it. The hole in the idea is when the same query is run with values that produce wildly different results. They should have different plans, but they don't. Whoever ran the query first helps to set the behavior for everyone who runs it afterwards.

A quick example: select * from [people] where lastname = 'SMITH' -- very popular last name in the US GO select * from [people] where lastname = 'BONAPARTE' -- NOT popular last name in the US

When the query for BONAPARTE is run, the plan that was built for SMITH will be re-used. If SMITH caused a table scan (which might be good, if the rows in the table are 99% SMITH), then BONAPARTE will also get a table scan. If BONAPARTE was run before SMITH, a plan using an index might be built and used, and then used again for SMITH (which might be better with the table scan). People might not notice that the performance for SMITH is poor since they expect bad performance since the entire table must be read and reading the index and hopping to the table isn't directly noticed.

With respect to your changes-that-should-change-anything, I suspect that SQL is just seeing that as a totally different query and building a new plan, specific to your value of [some number].

To test this, make a nonsensical change to the query, like adding some spaces between FOR and the table name, or put a comment on the end. Is it fast? If so, that's because that query is slightly different than what is in the cache, so SQL did what it does for "new" queries.

For a solution, I'd look at three things. First, make sure that your statistics are up to date. This really should be the first thing you do when a query seems to act weird or random. Your DBA should be doing this, but things happen. The usual way to ensure up-to-date statistics is to re-index your tables, which isn't necessarily a lightweight thing to do, but there are also options to just update the statistics.

The second thing to think about is to add indexes along the lines of Remus's suggestions. With a better/different index, one value versus another might be more stable and not vary so wildly.

If that doesn't help, the third thing to try is forcing a new plan every time you run the statement, using the RECOMPILE keyword:

select * from [big table] where serial_number = [some number] order by test_date desc OPTION (RECOMPILE)

There is an article describing a similar situation here. Frankly, I had only seen RECOMPILE applied to stored procedures before, but it seems to work with "regular" SELECT statements to. Kimberly Tripp has never steered me wrong.

You might also look into the feature called "plan guides", but it's more complex and might be overkill.

share|improve this answer
    
To cover some of these concerns: 1. Statistics have been updated, are are being updated. 2. We've tried indexing in several ways (covering indexes, etc) but the issue seems to be more tied to the order by usage against a datetime index specifically. 3. Just tried your idea with the RECOMPILE option, it still failed, which surprised me a bit, I was hoping it was going to work, although I don't know if it is a solution for production. –  DBtheDBA Oct 10 '12 at 21:46
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.