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: https://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:
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.
select id, test_date from [big table] where serial_number = ..... order by test_date
- I'm just wondering if theSELECT *
has a negative impact on your performance. If you have a nonclustered index ontest_date
and a clustered index onid
(assuming that's what it's called), this query should be covered by that nonclustered index and thus should return quite quicklysp_executesql
and see what happens.order by
operation.