6

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
David Basarab
  • 72,212
  • 42
  • 129
  • 156
davidsleeps
  • 9,393
  • 11
  • 59
  • 73
  • Please post your configuration code. Those startup times are much longer than anything I've experienced. – Jamie Ide Mar 30 '10 at 11:45
  • Yeah, there's definately something wrong there! As Jamie said though, you'll probably need to post the config code to get any useful help. – UpTheCreek Mar 30 '10 at 11:48
  • One thing you might want to do is configure log4net so that you can review the nhibernate log – UpTheCreek Mar 30 '10 at 11:56
  • Same size (plus the relationship tables)...the database is created using the schema export from nhibernate with no additional...anything! – davidsleeps Mar 30 '10 at 12:05
  • I hope you get an answer - I trialled nHibernate for a while but had similar problems and so walked away. However I'm in the 100's of tables camp. – CResults Mar 30 '10 at 12:07
  • That seems to say that the Dialect initializer takes at least 7 sec from that time. You could compile NHibernate yourself and profile what's up with that. – Pasi Savolainen Mar 30 '10 at 13:51
  • Did you try changing the NHibernate logger level as I suggested? Did it help? – Jamie Ide Apr 09 '10 at 12:15
  • Initially when I had the problem, I didn't have logging configured or even initialising in the global.asax...unless it was still logging in the background and needs to be disabled? I just presumed it was disabled until some configuration was added... – davidsleeps Apr 09 '10 at 12:40

2 Answers2

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>
Jamie Ide
  • 48,427
  • 16
  • 81
  • 117
1

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?

Meligy
  • 35,654
  • 11
  • 85
  • 109