Fun and Games with NHibernate and String Keys

One of the team spent much of yesterday banging his head against the wall. We had a query that took 18ms to run in Query Analyzer, and 1800ms to run from NHibernate. NHibernate Profiler would report 1800-2200 ms – and copying’n’pasting the exact same query statement into Query Analyzer would run it in < 20 ms. Running the same SQL statement via ADO.NET, from the same block of code, proved it wasn’t a network latency issue or anything - ADO.NET came back in 20ms, NHibernate still took over 2 seconds.

Finally, thanks to SQL Profiler, we managed to work out what was going on. The table in question had a primary key which was a varchar(9); in this instance, we were filtering on a particular primary key value – and NHibernate was specifying the value as an nvarchar(6), because NHibernate treats strings as unicode (nvarchar) by default. This C# code

currentSession
    .CreateCriteria<UserFeedItem>()
    .Add(Expression.Eq("User.UserCode", “abc123”)) // is a varchar(9) in the database for historical reasons
    .AddOrder(Order.Asc("Received"))
    .SetFirstResult(firstResult)
    .SetMaxResults(resultCount)
    .List<UserFeedItem>()
);

was resulting in the following SQL statement

exec sp_executesql
    N'SELECT TOP 50 FeedItemId16_0_, FeedUser16_0_, MailSent16_0_, ItemSeen16_0_, Deleted16_0_, Received16_0_
    FROM (
        SELECT this_.FeedItemId as FeedItemId16_0_, this_.FeedUser as FeedUser16_0_, this_.MailSent as MailSent16_0_, this_.ItemSeen as ItemSeen16_0_, this_.Deleted as Deleted16_0_, this_.Received as Received16_0_, ROW_NUMBER() OVER(ORDER BY this_.Received) as __hibernate_sort_row FROM Spotweb.dbo.[FeedUserFeedItem] this_ WHERE this_.FeedUser = @p0) as query WHERE query.__hibernate_sort_row > 50 ORDER BY query.__hibernate_sort_row',
    N'@p0 nvarchar(6)',
    @p0=N'abc123'

This means SQL Server has to do an implicit conversion when comparing your parameter value to the table’s primary key value – instead of using indexes, it has to retrieve every row, cast the primary key to an nvarchar(6), and then see whether the result is equal to your parameter. As you can imagine, this slows things down a little – especially on a table with several million records.

The immediate solution for this was to rewrite the code as follows:

currentSession
    .CreateQuery("from UserFeedItem where User.UserCode = :code")
    .SetParameter("code", “abc123”, TypeFactory.GetAnsiStringType(9))
    .SetFirstResult(firstResult)
    .SetMaxResults(resultCount)
    .List<UserFeedItem>()
);

- notice how on the third line we’re explicitly specifying TypeFactory.GetAnsiStringType(9) to force NHibernate to specify the parameter as a varchar(9). A better solution is to explicitly specify the mapping type for the column – we’re using Fluent NHibernate, so the mapping override code looks like this:

public class SiteUserOverrides : IAutoMappingOverride<SiteUser> {
    public void Override(AutoMapping<SiteUser> map) {
        map.Id(u => u.UserCode).CustomType(“AnsiString”);
    }
}

and now any reference in any query to a SiteUser.UserCode will be properly mapped as varchar instead of nvarchar.

Moral of the story: be careful with varchar and nvarchar keys when using NHibernate; make sure there aren’t implicit type conversions happening all over the place, because they can seriously mess up your performance.

It’s also worth noting that even the excellent NHibernate Profiler couldn’t shed any light on what was going on here – SQL Profiler (included with SQL Server) is still an incredibly powerful and under-used tool, and it’s well worth spending a couple of hours getting to grips with it.