How do I debug slow NHibernate Select query?

Question

I'm doing a simple query on the database, a search on two columns. I have an index on the columns. When I do the search in SQL Server Management Studio, it takes only a few milliseconds to complete (always less than 10). When I do the same query in NHibernate, it takes over 30 seconds. I've profiled the query, and the generated SQL is fine. I'm using NHibernate Profiler, and when I select "show query results" in NHibernate Profiler, it takes less than a second to get the results. Where do I go from here debugging this?

EDIT: So, I decided to do this using session.CreateSQLQuery(), and it works very fast. Why would this be faster than the other method?

EDIT: It seems as if using query parameters is the problem. I created an HQL query without parameters, and it was fine. As soon as I added named parameters, query execution time went up dramatically.

TABLE SCHEMA:

CREATE TABLE [dbo].[CRDefendant](
[Id] [int] NOT NULL,
[FirstName] [varchar](30) NULL,
[LastName] [varchar](30) NULL,
[MiddleName] [varchar](30) NULL,
[Race] [char](1) NULL,
[Sex] [char](1) NULL,
[BirthDate] [char](10) NULL,
[Social] [int] NULL,
[BadData] [varchar](50) NULL,
 CONSTRAINT [PK__CRDefend__3214EC073B95D2F1] PRIMARY KEY CLUSTERED 
(
    [Id] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [GROUP3]
) ON [GROUP3]

GO

QUERY:

SELECT this_.Id as Id16_0_, this_.FirstName as FirstName16_0_, this_.LastName as LastName16_0_, this_.MiddleName as MiddleName16_0_, this_.Race as Race16_0_, this_.Sex as Sex16_0_, this_.BirthDate as BirthDate16_0_, this_.Social as Social16_0_, this_.BadData as BadData16_0_ FROM [CRDefendant] this_ WHERE this_.LastName = @p0 and this_.FirstName like @p1

INDEX:

CREATE INDEX IX_CRDefendant_Name_DOB
ON CRDefendant (LastName ASC, FirstName ASC, BirthDate ASC)
INCLUDE (MiddleName, Race, Sex, Social)
ON GROUP3

Answer 1

To start with, post the exact query shown by the profiler and the query you run in SSMS. No offense, but what looks 'fine' to you may reveal a wealth of information to a trained eye. Second, post the exact schema of your tables, including all the indexes.

An example of possible problem could be nvarchar coercion due to datatype precedence (a search predicate with an nvarchar @variable on an varchar index will results into a full scan).

As for the more general question, how does one approach such an issue, the answer is: apply a method like Waits and Queues. All the information you need is available in various DMVs like sys.dm_exec_query_stats, sys.dm_exec_requests, sys.dm_db_index_usage_stats. The execution plan also reveals a lot about what s going on, but is significantly more difficult to interpret correctly the information in the execution plan.

Answer 2

How are you creating your query, with HQL or the criteria framework?

I have had the same situation. Running the SQL spit out by Nhibernate profiler was lightening quick, yet the app was running very slow. Switching from the criteria framework to HQL fixed the issue.

I think there is a bug/feature of the criteria framework that makes it really slow in some circumstances.

Answer 3

As well as Remus' answer (which addresses the idiotic treatment of (n)varchar by nHibernate), I'd add the column BadData to the INCLUDE clause too