NHibernate utiliza log4net como sistema de logging. Eso quiere decir que podemos aprovechar toda la potencia de log4net a la hora de decidir qué, cómo y dónde queremos loggear algo.

Mezclando este completo sistema de logging con la capacidad de NHibernate para mostrar las sentencias SQL, podemos tener una especie de profiler a lo pobre. Por supuesto, si necesitas algo más detallado puedes recurrir al profiler de tu base de datos o a soluciones comerciales para NHibernate, pero muchas veces no será necesario y nos bastará la información que podemos obtener del log de NHibernate para sacarnos de un apuro.

La única dificultad que tiene esto es configurar correctamente el nivel de log puesto que NHibernate genera una inmensa cantidad de información y es fácil perderse entre ella. Para almacenar las sentencias SQL generadas por NHibernate la configuración que debemos emplear en log4net es la siguiente:

<logger name="NHibernate">
    <level value=”ERROR”/>
</logger>

<logger name="NHibernate.SQL">
    <level value="DEBUG"/>
</logger>

Por la forma en que funciona log4net y sus logs jerárquicos, con la configuración anterior conseguimos que todos los mensajes de NHibernate sean guardados en el log sólo si su nivel de importancia es al menos ERROR, pero haremos que todos los mensajes de NHibernate.SQL queden registrados.

Además de esto, debemos indicar a NHibernate que muestre las sentencias SQL, para ello debemos configurar activar en la configuración de NHibernate el volcado de sentencias sql y (opcionalmente) el formateo de las mismas para hacerlas más legibles:

<?xml version="1.0" encoding="utf-8" ?>
<hibernate-configuration  xmlns="urn:nhibernate-configuration-2.2" >
    <session-factory>
        <property name="connection.driver_class">...</property>
        <property name="dialect">...</property>
        <property name="connection.connection_string">...</property>
        <property name="connection.provider">...</property>
        <property name="show_sql">true</property>
        <property name="format_sql">true</property>
    </session-factory>
</hibernate-configuration>

…y listo. Con esto ya tendremos en nuestro log todas la sentencias SQL que se están enviando a la base de datos. Hay que tener en cuenta que esto va a penalizar el rendimiento de la aplicación, por lo que sólo es recomendable activarlo cuando haya algún problema.

Jugando con la configuración de log4net, se pueden realizar auténticas perversiones con esto, del estilo de enviar un email a alguien cada vez que se inserta algo en la tabla X o cuando se actualiza un registro de la tabla Y. A veces es tentador acabar implementando alguna funcionalidad con esto, pero no es una buena idea. Si algo realmente tiene peso en la aplicación, debería quedar reflejado en ella y no aprovechar los resquicios que nos ofrecen estas herramientas.

En cualquier caso, la posibilidad de registrar las sentencias SQL generadas por NHibernate es una buena herramienta a tener en cuenta porque más de una vez nos puede sacar de un apuro y ayudarnos a resolver ese oscuro bug que sólo ocurre en producción las noches de luna llena.