Logging NHibernate SQL with log4net in ASP.NET

Posted by on 5/23/2009 03:59:00 PM

Have you ever wondered how to log the SQL generated by NHibernate?

This post tries to exemplify just that.

NHibernate uses HQL to leverage its expressiveness to the developer, but behind the scenes there is an engine that transforms the HQL into pure SQL that is executed against the database. This SQL can be logged so that you can see its structure and get a snapshot of what the database engine receives.

log4net is a logging tool that helps the developer see what SQL NHibernate is generating under the covers.

This is a brief description of log4net taken from its homepage:

log4net is a tool to help the programmer output log statements to a variety of output targets.

First and foremost you need to enable NHibernate logging in its configuration file. The property that sets this is hibernate.show_sql.

<add key="hibernate.show_sql" value="true" />

The following piece of code shows how to configure an appender and a logger that makes use of the appender. This code is kept inside the Web.config file in the log4net configuration section:

<appender name="NHibernateRollingFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="LogNHibernate.txt"/>
    <appendToFile value="true"/>
    <rollingStyle value="Size"/>
    <datePattern value="yyyyMMdd"/>
    <maxSizeRollBackups value="10"/>
    <maximumFileSize value="10MB"/>
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date - %message%newline"/>
    </layout>
</appender>

<logger name="NHibernateLogger" additivity="false">
    <level value="DEBUG"/> <!-- ALL, DEBUG, INFO, WARN, ERROR, FATAL or OFF -->
    <appender-ref ref="NHibernateRollingFileAppender"/>
</logger>

I’ll describe each part of the above code.

<appender name="NHibernateRollingFileAppender" type="log4net.Appender.RollingFileAppender">

Appender is an output destination. In this case its a RollingFileAppender. It writes logging events to a file in the file system.

<file value="LogNHibernate.txt"/>

The file property specifies the name of the file that’ll store the logs.

<appendToFile value="true"/>

The appendToFile property is set to true so that the appender will overwrite existing files.

<rollingStyle value="Size"/>

The rollingStyle property set how to roll log files. In this case the appender will roll log files based on the file size.

<datePattern value="yyyyMMdd"/>

To change the rolling period we need to set the datePattern property. It would be used if we adopted a rollingStyle based on Date instead of Size.

<maxSizeRollBackups value="10"/>
<maximumFileSize value="10MB"/>

Up to 10 old files of 10MB each will be kept. These rolled files will be named: LogNHibernate.txt.1, LogNHibernate.txt.2, LogNHibernate.txt.3, etc...

<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date - %message%newline"/>
</layout>

A layout enables us to customize the output format. This is accomplished by associating a layout with an appender.

The PatternLayout, lets the user specify the output format according to conversion patterns similar to the C language printf function.

<logger name="NHibernateLogger" additivity="false">

This is the logger and its additivity property controls appender accumulation, that is, how the logs are printed in the hierarchy of loggers.

For example, the output of a log statement of logger NHibernateLogger will go to all the appenders in NHibernateLogger and its ancestors. This is the meaning of the term "appender additivity".

<level value="DEBUG"/>

The level property controls the amount of information you want to be written to the log.

<appender-ref ref="NHibernateRollingFileAppender"/>

The property appender-ref specifies what appenders this logger uses.

That’s it! :-)

With this basic configuration you can start you search for points where NHibernate is generating to much queries where it shouldn’t.

I’m currently working on a performance branch where I’m learning how to deal with NHibernate lazy configuration.

This process of logging the SQL generated by NHibernate plays a great role when one is solving the bottlenecks involved in performance implications.

Just one note: keep in mind that the process of logging is by itself an onerous one. The amount of data that gets written by NHibernate is expressive and depending on the level of information you set inside the logger, the file size will grow very fast.

Hope this helps the fellow developers.

References

log4net homepage
http://logging.apache.org/log4net

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

log4net configuration examples
http://logging.apache.org/log4net/release/config-examples.html


Labels: , , , , , , ,