Using MiniProfiler Database Profiling with NHibernate

Question

What is the easiest way to use MiniProfiler profiling a database using NHibernate? In order for the profiler to work, I need to wrap the DbConnection that NHibernate uses in ProfiledDbConnection .

I'm not too familiar with NHibernate internals, so I don't know where all extensibility points are. (I noticed that NHibernate ISession has a Connection property, but it is read-only.)

Answer 1

[UPDATE] See the following links for the version using RealProxy for the proxy server. SqlCommand Package Support Now Supported

• blog http://blog.fearofaflatplanet.me.uk/mvcminiprofiler-and-nhibernate-take-2
• gist https://gist.github.com/1110153

I left the original answer unchanged since it was accepted. [/ UPDATE]

I managed to partially get this to work by implementing the Profiled Client Driver (an example for Sql Server 2008 below) - this works for simple examples, but I have not yet found a solution for NH batch processing (which tries to return the command back to SqlCommand)

 public class ProfiledSql2008ClientDriver : Sql2008ClientDriver { public override IDbCommand CreateCommand() { return new ProfiledDbCommand( base.CreateCommand() as DbCommand, null, MiniProfiler.Current); } public override IDbConnection CreateConnection() { return ProfiledDbConnection.Get( base.CreateConnection() as DbConnection, MiniProfiler.Current); } } 

Answer 2

I extended Roberts answer above to work with NHibernate doping. There is a lot of code, so it can be shortened, some of them are based on the nHibernate source for the client driver.

 <property name="connection.driver_class">YoureOnTime.Data.ProfiledSqlClientDriver, YoureOnTime.Common</property> public class ProfiledSqlClientDriver : DriverBase, IEmbeddedBatcherFactoryProvider { public override IDbConnection CreateConnection() { return new ProfiledSqlDbConnection( new SqlConnection(), MiniProfiler.Current); } public override IDbCommand CreateCommand() { return new ProfiledSqlDbCommand( new SqlCommand(), null, MiniProfiler.Current); } public override bool UseNamedPrefixInSql { get { return true; } } public override bool UseNamedPrefixInParameter { get { return true; } } public override string NamedPrefix { get { return "@"; } } public override bool SupportsMultipleOpenReaders { get { return false; } } public static void SetParameterSizes(IDataParameterCollection parameters, SqlType[] parameterTypes) { for (int i = 0; i < parameters.Count; i++) { SetVariableLengthParameterSize((IDbDataParameter)parameters[i], parameterTypes[i]); } } private const int MaxAnsiStringSize = 8000; private const int MaxBinarySize = MaxAnsiStringSize; private const int MaxStringSize = MaxAnsiStringSize / 2; private const int MaxBinaryBlobSize = int.MaxValue; private const int MaxStringClobSize = MaxBinaryBlobSize / 2; private const byte MaxPrecision = 28; private const byte MaxScale = 5; private const byte MaxDateTime2 = 8; private const byte MaxDateTimeOffset = 10; private static void SetDefaultParameterSize(IDbDataParameter dbParam, SqlType sqlType) { switch (dbParam.DbType) { case DbType.AnsiString: case DbType.AnsiStringFixedLength: dbParam.Size = MaxAnsiStringSize; break; case DbType.Binary: if (sqlType is BinaryBlobSqlType) { dbParam.Size = MaxBinaryBlobSize; } else { dbParam.Size = MaxBinarySize; } break; case DbType.Decimal: dbParam.Precision = MaxPrecision; dbParam.Scale = MaxScale; break; case DbType.String: case DbType.StringFixedLength: dbParam.Size = IsText(dbParam, sqlType) ? MaxStringClobSize : MaxStringSize; break; case DbType.DateTime2: dbParam.Size = MaxDateTime2; break; case DbType.DateTimeOffset: dbParam.Size = MaxDateTimeOffset; break; } } private static bool IsText(IDbDataParameter dbParam, SqlType sqlType) { return (sqlType is StringClobSqlType) || (sqlType.LengthDefined && sqlType.Length > MsSql2000Dialect.MaxSizeForLengthLimitedStrings && (DbType.String == dbParam.DbType || DbType.StringFixedLength == dbParam.DbType)); } private static void SetVariableLengthParameterSize(IDbDataParameter dbParam, SqlType sqlType) { SetDefaultParameterSize(dbParam, sqlType); // Override the defaults using data from SqlType. if (sqlType.LengthDefined && !IsText(dbParam, sqlType)) { dbParam.Size = sqlType.Length; } if (sqlType.PrecisionDefined) { dbParam.Precision = sqlType.Precision; dbParam.Scale = sqlType.Scale; } } public override IDbCommand GenerateCommand(CommandType type, SqlString sqlString, SqlType[] parameterTypes) { IDbCommand command = base.GenerateCommand(type, sqlString, parameterTypes); //if (IsPrepareSqlEnabled) { SetParameterSizes(command.Parameters, parameterTypes); } return command; } public override bool SupportsMultipleQueries { get { return true; } } #region IEmbeddedBatcherFactoryProvider Members System.Type IEmbeddedBatcherFactoryProvider.BatcherFactoryClass { get { return typeof(ProfiledSqlClientBatchingBatcherFactory); } } #endregion } public class ProfiledSqlClientBatchingBatcher : AbstractBatcher { private int batchSize; private int totalExpectedRowsAffected; private SqlClientSqlCommandSet currentBatch; private StringBuilder currentBatchCommandsLog; private readonly int defaultTimeout; public ProfiledSqlClientBatchingBatcher(ConnectionManager connectionManager, IInterceptor interceptor) : base(connectionManager, interceptor) { batchSize = Factory.Settings.AdoBatchSize; defaultTimeout = PropertiesHelper.GetInt32(NHibernate.Cfg.Environment.CommandTimeout, NHibernate.Cfg.Environment.Properties, -1); currentBatch = CreateConfiguredBatch(); //we always create this, because we need to deal with a scenario in which //the user change the logging configuration at runtime. Trying to put this //behind an if(log.IsDebugEnabled) will cause a null reference exception //at that point. currentBatchCommandsLog = new StringBuilder().AppendLine("Batch commands:"); } public override int BatchSize { get { return batchSize; } set { batchSize = value; } } protected override int CountOfStatementsInCurrentBatch { get { return currentBatch.CountOfCommands; } } public override void AddToBatch(IExpectation expectation) { totalExpectedRowsAffected += expectation.ExpectedRowCount; IDbCommand batchUpdate = CurrentCommand; string lineWithParameters = null; var sqlStatementLogger = Factory.Settings.SqlStatementLogger; if (sqlStatementLogger.IsDebugEnabled || log.IsDebugEnabled) { lineWithParameters = sqlStatementLogger.GetCommandLineWithParameters(batchUpdate); var formatStyle = sqlStatementLogger.DetermineActualStyle(FormatStyle.Basic); lineWithParameters = formatStyle.Formatter.Format(lineWithParameters); currentBatchCommandsLog.Append("command ") .Append(currentBatch.CountOfCommands) .Append(":") .AppendLine(lineWithParameters); } if (log.IsDebugEnabled) { log.Debug("Adding to batch:" + lineWithParameters); } currentBatch.Append(((ProfiledSqlDbCommand)batchUpdate).Command); if (currentBatch.CountOfCommands >= batchSize) { ExecuteBatchWithTiming(batchUpdate); } } protected void ProfiledPrepare(IDbCommand cmd) { try { IDbConnection sessionConnection = ConnectionManager.GetConnection(); if (cmd.Connection != null) { // make sure the commands connection is the same as the Sessions connection // these can be different when the session is disconnected and then reconnected if (cmd.Connection != sessionConnection) { cmd.Connection = sessionConnection; } } else { cmd.Connection = (sessionConnection as ProfiledSqlDbConnection).Connection; } ProfiledSqlDbTransaction trans = (ProfiledSqlDbTransaction)typeof(NHibernate.Transaction.AdoTransaction).InvokeMember("trans", System.Reflection.BindingFlags.GetField | System.Reflection.BindingFlags.NonPublic | System.Reflection.BindingFlags.Instance, null, ConnectionManager.Transaction, null); if (trans != null) cmd.Transaction = trans.Transaction; Factory.ConnectionProvider.Driver.PrepareCommand(cmd); } catch (InvalidOperationException ioe) { throw new ADOException("While preparing " + cmd.CommandText + " an error occurred", ioe); } } protected override void DoExecuteBatch(IDbCommand ps) { log.DebugFormat("Executing batch"); CheckReaders(); ProfiledPrepare(currentBatch.BatchCommand); if (Factory.Settings.SqlStatementLogger.IsDebugEnabled) { Factory.Settings.SqlStatementLogger.LogBatchCommand(currentBatchCommandsLog.ToString()); currentBatchCommandsLog = new StringBuilder().AppendLine("Batch commands:"); } int rowsAffected; try { rowsAffected = currentBatch.ExecuteNonQuery(); } catch (DbException e) { throw ADOExceptionHelper.Convert(Factory.SQLExceptionConverter, e, "could not execute batch command."); } Expectations.VerifyOutcomeBatched(totalExpectedRowsAffected, rowsAffected); currentBatch.Dispose(); totalExpectedRowsAffected = 0; currentBatch = CreateConfiguredBatch(); } private SqlClientSqlCommandSet CreateConfiguredBatch() { var result = new SqlClientSqlCommandSet(); if (defaultTimeout > 0) { try { result.CommandTimeout = defaultTimeout; } catch (Exception e) { if (log.IsWarnEnabled) { log.Warn(e.ToString()); } } } return result; } } public class ProfiledSqlClientBatchingBatcherFactory : IBatcherFactory { public virtual IBatcher CreateBatcher(ConnectionManager connectionManager, IInterceptor interceptor) { return new ProfiledSqlClientBatchingBatcher(connectionManager, interceptor); } } public class ProfiledSqlDbCommand : ProfiledDbCommand { public ProfiledSqlDbCommand(SqlCommand cmd, SqlConnection conn, MiniProfiler profiler) : base(cmd, conn, profiler) { Command = cmd; } public SqlCommand Command { get; set; } private DbTransaction _trans; protected override DbTransaction DbTransaction { get { return _trans; } set { this._trans = value; ProfiledSqlDbTransaction awesomeTran = value as ProfiledSqlDbTransaction; Command.Transaction = awesomeTran == null ? (SqlTransaction)value : awesomeTran.Transaction; } } } public class ProfiledSqlDbConnection : ProfiledDbConnection { public ProfiledSqlDbConnection(SqlConnection connection, MiniProfiler profiler) : base(connection, profiler) { Connection = connection; } public SqlConnection Connection { get; set; } protected override DbTransaction BeginDbTransaction(System.Data.IsolationLevel isolationLevel) { return new ProfiledSqlDbTransaction(Connection.BeginTransaction(isolationLevel), this); } } public class ProfiledSqlDbTransaction : ProfiledDbTransaction { public ProfiledSqlDbTransaction(SqlTransaction transaction, ProfiledDbConnection connection) : base(transaction, connection) { Transaction = transaction; } public SqlTransaction Transaction { get; set; } } 

Answer 3

Try to implement NHibernate.Connection.IConnectionProvider (you can just inherit DriverConnectionProvider ), in GetConnection() wrap IDbConnection as you need.

Connect the connection provider using the Environment.ConnectionProvider key in the configuration settings.

Answer 4

If anyone is interested, I did the integration using the custom Log4net appender instead. This way, I feel safe that I am not communicating with the Connection object.

The rough circuit is something like these lines: NHibernate emits sqlstrings as debug statements, and the appender configured in log4net.xml calls Start and Dispose on the MiniProfiler.