Problems with NHibernate and log4net - need some help

DerSteps · **Joined:** Thu Mar 06, 2008 8:27 am **Posts:** 7

Hibernate version: 1.2.1.4000, runtime version is v2.0.50727

Mapping documents: many...they work fine

Code between sessionFactory.openSession() and session.close(): none yet

Full stack trace of any exception that occurs: no exceptions

Name and version of the database you are using: MS SQL Server 2005 Express Edition

The generated SQL (show_sql=true): none yet

Hi there!

I have some problems using NHibernate together with log4net in my application.

I changed from Spring.NET to pure NHibernate and log4net, cause Spring.NET produced some errors I could not solve myself.

Well, now I have a performance problem which is caused by the logging of NHibernate loading at first application startup.

I am loading 55 mappings in the moment, thus creating a huge bunch of logging messages like this:

Code:

...

[10] DEBUG NHibernate.Cfg.Configuration (null) - dialect=NHibernate.Dialect.MsSql2000Dialect
[10] DEBUG NHibernate.Cfg.Configuration (null) - connection.provider=NHibernate.Connection.DriverConnectionProvider
[10] DEBUG NHibernate.Cfg.Configuration (null) - connection.connection_string=Server=(local);Database=studio;Uid=studio;Pwd=4Xi$=#-+;
[10] DEBUG NHibernate.Cfg.Configuration (null) - show_sql=false
[10] DEBUG NHibernate.Cfg.Configuration (null) - <-Studio.Database.NHibernate
[10] INFO NHibernate.Cfg.Configuration (null) - Searching for mapped documents in assembly: Studio.Database.NHibernate
[10] INFO NHibernate.Cfg.Configuration (null) - Mapping resource: Studio.Database.NHibernate.Mappings.FaxNumberCustomerNm.hbm.xml
[10] INFO NHibernate.Dialect.Dialect (null) - Using dialect: NHibernate.Dialect.MsSql2000Dialect
[10] INFO NHibernate.Cfg.HbmBinder (null) - Mapping class: Studio.Database.NHibernate.Model.FaxNumberCustomerNm -> fax_numbers_customers_nm
[10] DEBUG NHibernate.Cfg.HbmBinder (null) - Mapped property: Id -> fax_number_customer_nm_id, type: Int32
[10] DEBUG NHibernate.Cfg.HbmBinder (null) - Mapped property: FaxNumber -> fax_number_id, type: FaxNumber
[10] DEBUG NHibernate.Cfg.HbmBinder (null) - Mapped property: Customer -> customer_id, type: Customer

...

[10] DEBUG NHibernate.Cfg.Configuration (null) - properties: System.Collections.Hashtable
[10] INFO NHibernate.Cfg.Configuration (null) - checking mappings queue
[10] INFO NHibernate.Cfg.Configuration (null) - processing one-to-many association mappings
[10] INFO NHibernate.Cfg.Configuration (null) - processing one-to-one association property references
[10] INFO NHibernate.Cfg.Configuration (null) - processing foreign key constraints

...

References are resolved here

...

[10] INFO NHibernate.Dialect.Dialect (null) - Using dialect: NHibernate.Dialect.MsSql2000Dialect
[10] INFO NHibernate.Connection.ConnectionProviderFactory (null) - Initializing connection provider: NHibernate.Connection.DriverConnectionProvider
[10] INFO NHibernate.Connection.ConnectionProvider (null) - Configuring ConnectionProvider
[10] INFO NHibernate.Cfg.SettingsFactory (null) - Transaction factory: NHibernate.Transaction.AdoNetTransactionFactory
[10] INFO NHibernate.Cfg.SettingsFactory (null) - Optimize cache for minimal puts: False
[10] INFO NHibernate.Cfg.SettingsFactory (null) - Connection release mode: auto
[10] INFO NHibernate.Cfg.SettingsFactory (null) - Query translator: NHibernate.Hql.Classic.ClassicQueryTranslatorFactory
[10] INFO NHibernate.Cfg.SettingsFactory (null) - Query language substitutions: {}
[10] INFO NHibernate.Cfg.SettingsFactory (null) - cache provider: NHibernate.Cache.NoCacheProvider, NHibernate, Version=1.2.1.4000, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
[10] INFO NHibernate.Impl.SessionFactoryImpl (null) - building session factory
[10] DEBUG NHibernate.Impl.SessionFactoryImpl (null) - instantiating session factory with properties: {connection.connection_string=Server=(local);Database=studio;Uid=studio;Pwd=4Xi$=#-+;, hibernate.connection.connection_string=Server=(local);Database=studio;Uid=studio;Pwd=4Xi$=#-+;, dialect=NHibernate.Dialect.MsSql2000Dialect, hibernate.show_sql=false, hibernate.use_reflection_optimizer=true, hibernate.dialect=NHibernate.Dialect.MsSql2000Dialect, connection.provider=NHibernate.Connection.DriverConnectionProvider, hibernate.connection.provider=NHibernate.Connection.DriverConnectionProvider, show_sql=false}
[10] DEBUG NHibernate.Impl.SessionFactoryObjectFactory (null) - initializing class SessionFactoryObjectFactory
[10] DEBUG NHibernate.Impl.SessionFactoryObjectFactory (null) - registered: 1320a96c3b5d4528be1bcf4735e6fccf(unnamed)
[10] INFO NHibernate.Impl.SessionFactoryObjectFactory (null) - no name configured

...

[10] DEBUG NHibernate.Loader.Entity.AbstractEntityLoader (null) - Static select for entity Studio.Database.NHibernate.Model.FaxNumberCustomerNm: SELECT faxnumberc0_.fax_number_customer_nm_id as fax1_0_3_, faxnumberc0_.fax_number_id as fax2_0_3_, faxnumberc0_.customer_id as customer3_0_3_, faxnumber1_.fax_number_id as fax1_42_0_, faxnumber1_.fax_number_number as fax2_42_0_, faxnumber1_.fax_number_country_pre as fax3_42_0_, faxnumber1_.fax_number_pre as fax4_42_0_, faxnumber1_.fax_number_name as fax5_42_0_, faxnumber1_.fax_number_comment as fax6_42_0_, customer2_.customer_id as customer1_49_1_, customer2_.customer_birthday as customer2_49_1_, customer2_.customer_comment as customer3_49_1_, customer2_.customer_name_id as customer4_49_1_, customerna3_.customer_name_id as customer1_11_2_, customerna3_.customer_first_name as customer2_11_2_, customerna3_.customer_middle_name as customer3_11_2_, customerna3_.customer_last_name as customer4_11_2_, customerna3_.customer_title as customer5_11_2_ FROM fax_numbers_customers_nm faxnumberc0_ left outer join fax_numbers faxnumber1_ on faxnumberc0_.fax_number_id=faxnumber1_.fax_number_id left outer join customers customer2_ on faxnumberc0_.customer_id=customer2_.customer_id left outer join customer_names customerna3_ on customer2_.customer_name_id=customerna3_.customer_name_id WHERE faxnumberc0_.fax_number_customer_nm_id=?
[10] DEBUG NHibernate.Loader.Entity.AbstractEntityLoader (null) - Static select for entity Studio.Database.NHibernate.Model.FaxNumberCustomerNm: SELECT faxnumberc0_.fax_number_customer_nm_id as fax1_0_3_, faxnumberc0_.fax_number_id as fax2_0_3_, faxnumberc0_.customer_id as customer3_0_3_, faxnumber1_.fax_number_id as fax1_42_0_, faxnumber1_.fax_number_number as fax2_42_0_, faxnumber1_.fax_number_country_pre as fax3_42_0_, faxnumber1_.fax_number_pre as fax4_42_0_, faxnumber1_.fax_number_name as fax5_42_0_, faxnumber1_.fax_number_comment as fax6_42_0_, customer2_.customer_id as customer1_49_1_, customer2_.customer_birthday as customer2_49_1_, customer2_.customer_comment as customer3_49_1_, customer2_.customer_name_id as customer4_49_1_, customerna3_.customer_name_id as customer1_11_2_, customerna3_.customer_first_name as customer2_11_2_, customerna3_.customer_middle_name as customer3_11_2_, customerna3_.customer_last_name as customer4_11_2_, customerna3_.customer_title as customer5_11_2_ FROM fax_numbers_customers_nm faxnumberc0_ left outer join fax_numbers faxnumber1_ on faxnumberc0_.fax_number_id=faxnumber1_.fax_number_id left outer join customers customer2_ on faxnumberc0_.customer_id=customer2_.customer_id left outer join customer_names customerna3_ on customer2_.customer_name_id=customerna3_.customer_name_id WHERE faxnumberc0_.fax_number_customer_nm_id=?
[10] DEBUG NHibernate.Loader.Entity.AbstractEntityLoader (null) - Static select for entity Studio.Database.NHibernate.Model.FaxNumberCustomerNm: SELECT faxnumberc0_.fax_number_customer_nm_id as fax1_0_0_, faxnumberc0_.fax_number_id as fax2_0_0_, faxnumberc0_.customer_id as customer3_0_0_ FROM fax_numbers_customers_nm faxnumberc0_ with (updlock, rowlock) WHERE faxnumberc0_.fax_number_customer_nm_id=?
[10] DEBUG NHibernate.Loader.Entity.AbstractEntityLoader (null) - Static select for entity Studio.Database.NHibernate.Model.FaxNumberCustomerNm: SELECT faxnumberc0_.fax_number_customer_nm_id as fax1_0_0_, faxnumberc0_.fax_number_id as fax2_0_0_, faxnumberc0_.customer_id as customer3_0_0_ FROM fax_numbers_customers_nm faxnumberc0_ with (updlock, rowlock) WHERE faxnumberc0_.fax_number_customer_nm_id=?

...

[10] DEBUG NHibernate.Impl.SessionFactoryImpl (null) - Instantiated session factory

And that's just the log-excerpt for one mapped class...

The application startup needs somewhat more than 60 seconds, sometimes even the CLR complains about being ignored for such a long time...

This is my app.config file:

Code:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

  <configSections>
    <section name="hibernate-configuration" type="NHibernate.Cfg.ConfigurationSectionHandler, NHibernate"/>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>

  <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
    <session-factory>
      <property name="dialect">NHibernate.Dialect.MsSql2000Dialect</property>
      <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
      <property name="connection.connection_string">Server=(local);Database=studio;Uid=studio;Pwd=;</property>
      <property name="show_sql">false</property>
      <mapping assembly="Studio.Database.NHibernate"/>
      
    </session-factory>

    
  </hibernate-configuration>

  <log4net debug="false">

    <appender name="TraceAppender" type="log4net.Appender.TraceAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5level %M - %message%newline" />
      </layout>

    </appender>


    <root>
      <level value="OFF" />
      <appender-ref ref="TraceAppender"/>
    </root>
    
    <category name="NHibernate">
      <level value="OFF"/>
    </category>
    
    <logger name="Logger">
      <level value="OFF"/>
      <appender-ref ref="TraceAppender" />
    </logger>

    <logger name="NHibernate.Loader.Entity.AbstractEntityLoader">
      <level value="OFF"/>
      <appender-ref ref="TraceAppender"/>
    </logger>
    
  </log4net>
  
</configuration>

As you can see, I even tried to disable logging - which did not change anything at all...quite strange?

What I am wondering about is that in the app.config, everything from the line

Code:

is highlighted by Visual Studio as containing errors (are there any errors?).

Could you help me out with that problem? I need to disable the logs for NHibernate startup to speed up my application...

As I said above, I got used to NHibernate and log4net by using Spring.NET, so I am not sure if I got everything right or did something wrong.

And as I am posting: I'd like to put NHibernate and log4net config files in single files each, like for example:

Code:

[MyApp]
   - [Configs]
      - NHibernateConfig.xml
      - log4netConfig.xml
   - App.config

How do I do this? Maybe it's a dumb question, but I simply just don't know.

Thanks in advance - Steps

jta · **Posted:** Fri Mar 14, 2008 7:29 am

Have you tried setting the level to FATAL ?

And if you don't need logging couldn't you just remove the log4.net.Configure() call in your application?

wolli · **Posted:** Fri Mar 14, 2008 9:51 am

The only major differences to my configuration are, that I have specified the assembly in the appender section:

Code:

and don't have a category section but a logger instead:

Code:

    <logger name="NHibernate">
      <level value="OFF" />
    </logger>

The rest of my configuration is pretty much the same and setting a logger to OFF works fine.

DerSteps · **Joined:** Thu Mar 06, 2008 8:27 am **Posts:** 7

Hi!

I changed my config to this:

Code:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

  <configSections>
    <section name="hibernate-configuration" type="NHibernate.Cfg.ConfigurationSectionHandler, NHibernate"/>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>

  <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
    <session-factory>
      <property name="dialect">NHibernate.Dialect.MsSql2000Dialect</property>
      <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
      <property name="connection.connection_string">Server=(local);Database=studio;Uid=studio;Pwd=;</property>
      <property name="show_sql">false</property>
      <mapping assembly="Studio.Database.NHibernate"/>
      
    </session-factory>

    
  </hibernate-configuration>

  <log4net debug="false">

    <appender name="TraceAppender" type="log4net.Appender.TraceAppender, log4net">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5level %M - %message%newline" />
      </layout>

    </appender>


    <root>
      <level value="OFF" />
      <appender-ref ref="TraceAppender"/>
    </root>
    
    <logger name="NHibernate">
      <level value="OFF"/>
    </logger>
    

    <logger name="Logger">
      <level value="OFF"/>
      <appender-ref ref="TraceAppender" />
    </logger>

    <logger name="NHibernate.Loader.Entity.AbstractEntityLoader">
      <level value="OFF"/>
      <appender-ref ref="TraceAppender"/>
    </logger>
    
  </log4net>
  
</configuration>

But the messages still keep coming.

I tried almost every logging level, but this won't change anything. Which is quite weird, cause I am getting loads of DEBUG and INFO messages...

Greets - Steps

wolli · **Posted:** Fri Mar 14, 2008 10:08 am

How and when are you configuring log4net in your application (e.g. before or after building the session factory) ?

mabraham · **Joined:** Mon Mar 20, 2006 10:49 pm **Posts:** 59

Try setting debug="true" on the log4net element. That will cause log4net to dump a lot of info as it configures itself. You may find some clues to your problem.

DerSteps · **Joined:** Thu Mar 06, 2008 8:27 am **Posts:** 7

I am configuring log4net like this in Program.cs:

Code:

Application.EnableVisualStyles();
Application.SetCompatibleTextRenderingDefault(false);

BasicConfigurator.Configure();
            
Application.Run(new Form1());

The class that is supposed to handle NHibernate is a singleton:

Code:

public sealed class NHibernateManager
{
    private static readonly ILog LOG = LogManager.GetLogger("Logger");

    public static readonly NHibernateManager Instance = new NHibernateManager();

    private ISessionFactory _factory;

    private NHibernateManager()
    {
        this._factory = new Configuration().Configure().BuildSessionFactory();
        
        LOG.Info("Session factory has been created successfully");
    }

    public void Test()
    {
        LOG.Info("Hello from NHibernate Manager");
    }
}

Could that be a problem?

Greets - Steps

wolli · **Posted:** Fri Mar 14, 2008 11:11 am

I'm not really an expert in configuring log4net, but reading this example

http://logging.apache.org/log4net/release/manual/configuration.html

BasicConfigurator seems to use a hardcoded configuration, implying that your configuration is ignored. Try to use the XmlConfigurator instead. There is an example on that page, too.

DerSteps · **Joined:** Thu Mar 06, 2008 8:27 am **Posts:** 7

Yeah, this changed everything!

Now it works fine!

Thank you a lot, wolli!

Greets - Steps