NHibernate and interceptors - measuring/monitoring SQL round-trip times

Question

In order to get early-warning of a slow or potentially slow areas, I'd like to have an Interceptor for NHibernate that can act as a performance monitor, so that any database operation that takes more than a given time raises an event and (importantly) a full stacktrace into the application's logs.

Interceptors seemed to be a good window into this. However, having experimented, there doesn't seem to be anyway to catch a "just-back-from-SQL" event:

• OnPreFlush and OnPostFlush work on full batches where writes are involved, but aren't invoked on read events.
• OnPrepareStatement() seems to be the best to put start measuring, but to stop?
• For read events, OnLoad might be the place to stop the clock, but it's called once-per-entity returned - how do I know when I've got to the end of all entities?
• For write events, I can't see any post-SQL event (other than those that work on the entire batch - OnPostFlush and OnAfterTransaction; I get the impression OnSave, OnFlushDirty, etc are called before the actual database call occurs - happy to be corrected though).

From what I can tell, documentation is heavily lacking on exactly what the pipeline order is with NHibernate's interaction with the database, and thus when in that pipeline different events and interceptor calls are called in relation to the actual SQL execution itself.

This is something that needs to be permanently available, sitting in the background, pretty much that requires no human intervention except when slow queries are detected. It also needs to run headless on a large farm of servers, so interactive tools such as NHibernate Profiler are out: it's literally something that we can enable and forget about, letting it log as and when appropriate.

Is there anything I have missed or misunderstood?

Answer 1

I had a similar problem. I wanted measure and log all queries that goes through NHibernate. What I did is I wrote a custom batching factory (in this case I work with oracle) but you can apply the same technique to any db:

1-) Implement batcher factory, (in this case I am extending existing factory)

public class OracleLoggingBatchingBatcherFactory : OracleDataClientBatchingBatcherFactory
{
    public override IBatcher CreateBatcher(ConnectionManager connectionManager, IInterceptor interceptor)
    {
        return new OracleLoggingBatchingBatcher(connectionManager, interceptor);
    }
}

2-) Implement the Batcher itself (in this case I am extending existing batcher). Make sure you inherit IBatcher again since we want our new methods to be called

public class OracleLoggingBatchingBatcher : OracleDataClientBatchingBatcher, IBatcher
{
      .... // here override ExecuteNonQuery, DoExecuteBatch and ExecuteReader. 
           //You can do all kind of intercepting, logging or measuring here
           //If they are not overrideable just implement them and use "new" keyword if necessary
           //since we inherit IBatcher explicitly it will work polymorphically.
           //Make sure you call base implementation too or re-implement the method from scratch
}

3-) Register the factory via NHibernate config:

    <property name="adonet.factory_class">OracleLoggingBatchingBatcherFactory, MyAssembly</property>