NHibernate: Criteria query slow in web app but fast in unit tests, why?

I am having a problem where a criteria query in NHibernate is executes in less then a second when I run it in a unit test, but when I try to run it from the context of my web application, it takes over a minute. Both are hitting the same database for the same data.

My NHibernate mapping:

var properties = new Dictionary<string, string>();
var configuration = new Configuration();

properties.Add("connection.provider", "NHibernate.Connection.DriverConnectionProvider");
properties.Add("proxyfactory.factory_class", "NHibernate.Bytecode.DefaultProxyFactoryFactory, NHibernate");
properties.Add("connection.release_mode", "on_close");
properties.Add("current_session_context_class", "web");
properties.Add("dialect", "NHibernate.Dialect.MsSql2005Dialect");
properties.Add("connection.connection_string_name", "DBConnection");
configuration.Properties = properties;
SessionFactory = configuration.BuildSessionFactory();

The only difference in this mapping between tests and the web app is the current_session_context_class, where it is thread_static in tests, but that does not seem to be the problem.

The criteria for the query:

var reports =   Session.CreateCriteria&l开发者_StackOverflowt;Report>()
        .SetFetchMode("Site", FetchMode.Join)
        .SetFetchMode("Actions", FetchMode.Join)
        .SetResultTransformer(new DistinctRootEntityResultTransformer())
        .Add(Subqueries.PropertyIn("Site",
            SiteCriteria.GetSitesForUserWithPermission(user, Permission.SomePermission))))
        .List<Report>();

I have tried using NH Profiler to help, but it did not offer any useful suggestions.

edit: Looking further in nhprofiler, I see that in the test for example, the query duration is 1ms / 313ms (Database only / Total). But for the website it just took me 1ms / 43698ms. It seems that NHibernate is having a hard time mapping the actual objects.

The difference between the unit tests and the web app is that unit tests aren't logged. I added to our log4net.config:

<filter type="log4net.Filter.LevelRangeFilter">
    <levelMin value="WARN" />
</filter>

And the problem went away.

It was outputting a lot of stuff like this:

2011-07-21 13:07:17,479 DEBUG [14] LoadContexts - attempting to locate loading collection entry [CollectionKey[Actions#d6adfe87-a7d4-4821-bb10-4ef76fcf614d]] in any result-set context
2011-07-21 13:07:17,481 DEBUG [14] LoadContexts - collection [CollectionKey[Actions#d6adfe87-a7d4-4821-bb10-4ef76fcf614d]] not located in load context

Visual Studio Debugger is the culprit! Try running your app with debugging off (ctrl+F5) or run it from outside of visual studio. I did this and my app ran as fast as the unit test.

If this solves the problem there are a few things you can do to speed up VS Debugger like removing all the breakpoints and deleting the .suo file. For more info see this post: Slow debugging issue in Visual Studio

Other things that might help:

1. Try setting the correct default database for the user you're connected as. Do this on sql server itself (using SSMS for example) not in any of the configs.
2. Turn log4net logging completely off using the threshold property like so in the app/web config: <log4net debug="false" threshold="off">.
3. Set the default_schema in your hibernate config.
4. Turn show_sql off in the hibernate config.