Monday, November 21, 2011

sp_executesql executes extremely slowly

On a legacy system, we had a query that in query analyzer is very fast, around a millisecond.
But in production it is slower than molasses in winter, up to three seconds.
The table being queried is simple and tall, around 25 million rows, with a clustered index on "bid":
CREATE TABLE [dbo].[BookHistory] (
[bid] [varchar] (64) COLLATE SQL_Latin1_General_CP1_CI_AS  NOT NULL,
[source] [varchar] (16) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL,
[src] [varchar] (32) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL,  
[bookCode] [varchar] (32) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[bookStatus] [varchar] (32) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[actionTime] [datetime] NOT NULL 
) ON [PRIMARY]
GO
CREATE CLUSTERED INDEX [BID_INDEX] ON [dbo].[BookHistory] 
(
 [bid] ASC
)
GO
The code is trying to retrieve all the records, typically a dozen, for a particular "bid" which should be faster than greased lightening.
exec sp_executesql N'SELECT bookCode as name,bookStatus,
DATEDIFF(DAY, actionTime, GETDATE()) as days  
FROM BookHistory with(nolock) 
WHERE bid = @bid AND source = @source AND src = @src'
,N'@source nvarchar(5),@bid nvarchar(10),@src nvarchar(4000)'

As the more astute of you can probably see now, the issue is with the data type of "bid". In the database it's a varchar(64), but in the trace it's a nvarchar(4000).
In the C# code the type of the parameter of "bid" was left to the default, which is "nvarchar", so...... SQL server was thinking, "I've got this nifty little index for 'bid', too bad I can't use it since the incoming query is an 'nvarchar', oh well, I guess I'll do a scan and convert all those 'bid' thingys to nvarchar on the fly." That's why the SQL statement was glacial.
For the interim, I patched the SQL statement with a cast, since that can be done without a full deployment, to be
exec sp_executesql N'SELECT bookCode as name,
bookStatus,DATEDIFF(DAY, actionTime, GETDATE()) as days  
FROM BookHistory with(nolock)
 WHERE bid = cast(@bid as varchar(64)) AND source = @source AND src = @src',
N'@source nvarchar(5),@bid nvarchar(10),@src nvarchar(4000)'
And the statement that used to take a few seconds now takes a few milliseconds. Mystery solved.
Postmortem: The clue was that the execution plan was doing a scan instead of using the real index.
Moral: Always set the type of the SQL parameter when using SqlCommand directly.
Moral2: Don't use SqlCommand directly. Use NHibernate or some other ORM so it can figure out all that stuff for you (Although in legacy systems you don't always have that luxury).

No comments: