NHibernate: Display executed SQL at the bottom of an ASP.NET page (MVC or WebForms)

Almost every modern application that uses relational database is build on top of ORM tool. The ORM tools can significantly decrease the efforts for interacting with the database, but unfortunately most of the developers are not familiar with the SQL code that is produced by the ORM tools. I’m not hiding that my favorite ORM is NHibernate. I’m using it since early beta, but from time to time even I’m surprised by the produced SQL. So, you need to monitor closely what SQL is executed. This blog post will describe one not widely used but very useful approach – the executed SQL will be displayed as a footer on any ASP.NET web page. It does not matter if the web page is using MVC or WebForms. Interested? Then continue reading.

Currently, there are several ways to display the SQL produced by NHibernate:

• Database profiler tool – some of the modern RDBMS systems are coming with a profiler tool that can hook to the database engine and display the executed SQL. For example SQL Server comes with SQL Server Profiler. Unfortunately the SQL Server Express edition is missing this tool.
• NHibernate Profiler – this is a third party tool that hooks to your application and monitors the NHibernate. Comes with cool WPF UI interface and lots of other features. Unfortunately at the time of writing you will need to purchase a license to use it. As well you will need to switch from your application to the tool after each action to monitor the produced SQL.
• Log4Net – you can configure the log4net library to save the produced SQL to a file for example. Unfortunately reading long files with SQL statements is too boring. Sometimes it is tricky to figure out the SQL executed as a result of single action.
• Display the executed SQL at the bottom of an ASP.NET web page. The idea is to have an IHttpModule module that will inject the SQL code at the end of each request. This approach saves time, because the SQL is visible instantaneously after the action is executed. Unfortunately this trick works only for web applications.

There are several ways to access the SQL that has been executed by NHibernate. I will use a NHibernate interceptor. The code for the interceptor looks like this:

public class NHibernateSQLMonitor : EmptyInterceptor
{
    public static void Init(Configuration config)
    {
        config.SetInterceptor(new NHibernateSQLMonitor());
    }

    private static StringBuilder mExecutedSQL = new StringBuilder();

    public static string ExecutedSQL
    {
        get
        {
            return mExecutedSQL.ToString();
        }
    }

    public static void ClearExecutedSQL()
    {
        mExecutedSQL = new StringBuilder();
    }

    public override NHibernate.SqlCommand.SqlString OnPrepareStatement(
        NHibernate.SqlCommand.SqlString sql)
    {
        mExecutedSQL.AppendLine(sql.ToString());

        return base.OnPrepareStatement(sql);
    }
}

The important method is OnPrepareStatement. This method is invoked every time NHibernate executes SQL statement. The sql parameter holds the SQL that will be executed.

Before using it, the interceptor must be registered. One possible way to do it is like this:

NHibernate.Cfg.Configuration cfg = new NHibernate.Cfg.Configuration();
NHibernateSQLMonitor.Init(cfg);

ISessionFactory sessionFactory = cfg.BuildSessionFactory();

Now everything is ready for our IHttpModule that will inject the executed SQL at the bottom of a web page. Here is the implementation:

public class NHibernateSQLMonitorModule : IHttpModule
{
    public void Init(HttpApplication context)
    {
        context.PostRequestHandlerExecute += new EventHandler(
  PostRequestHandlerExecute);
    }

    void PostRequestHandlerExecute(object sender, EventArgs e)
    {
        HttpContext httpContext = ((HttpApplication)sender).Context;
        HttpResponse response = httpContext.Response;

        if (response.StatusCode == 302)
        {
            //Browser performs redirect. Do nothing.
            //The executed SQL will be shown on the next page
        }
        else if (response.ContentType == "text/html")
        {
            response.Write("<hr>");
            response.Write("<b>SQL Executed by NHibernate</b>");
            response.Write("<br>");

            string executedSQL = NHibernateSQLMonitor.ExecutedSQL.Replace(
   "\n", "<br>");
            response.Write(executedSQL);

            NHibernateSQLMonitor.ClearExecutedSQL();
        }
    }

    public void Dispose()
    {
        //Not required
    }
}

Now there is one final step that should be done – the HttpModule needs to be registered in the config file of the application. To do it open the web.config file, find the <httpModules> section (<modules> if you are running IIS7) and place the following line there:

<add name="NHibernateSQLMonitor"
 type="Data.NHibernateSQLMonitorModule, Data"/>

Data is the assembly name where the NHibernateSQLMonitorModule class is defined. Now everything is ready and if there are no compilation errors you should see something like this:

After adding new record, the page will look like this:

So, what about improvements:

Instead of using NHibernate interceptor for monitoring the executed SQL it is possible to display the output from the Log4Net. The log4net output contains the SQL parameter values which may be a great benefit. As you may have noticed, the values in the screenshot above are replaced by the ? character.

The current version uses static variable to hold the executed SQL. If there is more than one user interacting with the application, this will lead to some synchronization problems. For example, you can extend the NHibernateSQLMonitor class to use the ASP.NET Session store. This way the user will see only the SQL code executed as a result of his actions.

P.S. This post was inspired long time ago after reading the Steve Sanderson’s Pro ASP.NET MVC Framework. He has a similar application that connects to Linq to SQL and displays the executed SQL.