nhibernate configure and buildsessionfactory time

Question

I'm using Nhibernate as the OR/M tool for an asp.net application and the startup performance is really frustrating. Part of the problem is definitely me in my lack of understanding but I've tried a fair bit (understanding is definitely improving) and am still getting nowhere.

Currently ANTS profiler has that the Configure() takes 13-18 seconds and the BuildSessionFActory() as taking about 5 seconds. From what i've read, these times might actually be pretty good, but they were generally talking about hundreds upon hundreds of mapped entities...this project only has 10.

I've combined all the mapping files into a single hbm mapping file and this did improve things but only down to the times mentioned above...

I guess, are there any "Traps for young players" that are regularly missed...obvious "I did this/have you enabled that/exclude file x/mark file y as z" etc...

I'll try the serialize the configuration thing to avoid the Configure() stage, but I feel that part shouldn't be that long for that amount of entities and so would essentially be hiding a current problem...

I will post source code or configuration if necessary, but I'm not sure what to put in really...

thanks heaps!

edit (more info)
I'll also add that once this is completed, each page is extremely quick...

configuration code- hibernate.cfg.xml

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="hibernate-configuration"
    type="NHibernate.Cfg.ConfigurationSectionHandler, NHibernate" />
  </configSections>
  <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
    <session-factory>
      <property name="dialect">NHibernate.Dialect.MsSql2005Dialect</property>
      <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
      <property name="connection.driver_class">NHibernate.Driver.SqlClientDriver</property>
      <property name="connection.connection_string_name">MyAppDEV</property>
      <property name="cache.provider_class">NHibernate.Caches.SysCache.SysCacheProvider, NHibernate.Caches.SysCache</property>
      <property name="cache.use_second_level_cache">true</property>
      <property name="show_sql">false</property>
      <property name="proxyfactory.factory_class">NHibernate.ByteCode.Castle.ProxyFactoryFactory, NHibernate.ByteCode.Castle</property>
      <property name="current_session_context_class">managed_web</property>

      <mapping assembly="MyApp.Domain"/>
    </session-factory>
  </hibernate-configuration>
</configuration>

My SessionManager class which is bound and unbound in a HttpModule for each request

Imports NHibernate
Imports NHibernate.Cfg

Public Class SessionManager

    Private ReadOnly _sessionFactory As ISessionFactory

    Public Shared ReadOnly Property SessionFactory() As ISessionFactory
        Get
            Return Instance._sessionFactory
        End Get
    End Property

    Private Function GetSessionFactory() As ISessionFactory
        Return _sessionFactory
    End Function

    Public Shared ReadOnly Property Instance() As SessionManager
        Get
            Return NestedSessionManager.theSessionManager
        End Get
    End Property

    Public Shared Function OpenSession() As ISession
        Return Instance.GetSessionFactory().OpenSession()
    End Function

    Public Shared ReadOnly Property CurrentSession() As ISession
        Get
            Return Instance.GetSessionFactory().GetCurrentSession()
        End Get
    End Property

    Private Sub New()
        Dim configuration As Configuration = New Configuration().Configure()
        _sessionFactory = configuration.BuildSessionFactory()
    End Sub

    Private Class NestedSessionManager
        Friend Shared ReadOnly theSessionManager As New SessionManager()
    End Class

End Class

edit 2 (log4net results)

will post bits that have a portion of time between them and will cut out the rest...

2010-03-30 23:29:40,898 [4] INFO  NHibernate.Cfg.Environment [(null)] - Using reflection optimizer
2010-03-30 23:29:42,481 [4] DEBUG NHibernate.Cfg.Configuration [(null)] - dialect=NHibernate.Dialect.MsSql2005Dialect

...

2010-03-30 23:29:42,501 [4] INFO  NHibernate.Cfg.Configuration [(null)] - Mapping resource: MyApp.Domain.Mappings.hbm.xml
2010-03-30 23:29:43,342 [4] INFO  NHibernate.Dialect.Dialect [(null)] - Using dialect: NHibernate.Dialect.MsSql2005Dialect
2010-03-30 23:29:50,462 [4] INFO  NHibernate.Cfg.XmlHbmBinding.Binder [(null)] - Mapping class: 

...

2010-03-30 23:29:51,353 [4] DEBUG NHibernate.Connection.DriverConnectionProvider [(null)] - Obtaining IDbConnection from Driver
2010-03-30 23:29:53,136 [4] DEBUG NHibernate.Connection.ConnectionProvider [(null)] - Closing connection

Answer 1

Try changing the logging level for the NHibernate logger. It appears that you have it set to DEBUG, which is probably fine for your app., but will cause NHibernate to do a tremendous amount of logging.

<log4net>
  ....
  <logger name="NHibernate">
      <level value="ERROR"/>
  </logger>
</log4net>

Answer 2

Did you try to remove the cache-related code from the configuration?

Also, did you try grabbing the latest trunk versions of NHibernate and Castle?