Using MiniProfiler's database profiling with NHibernate

Solution 1:

[UPDATE] Please see the following links for a version of that uses RealProxy to proxy the SqlCommand - batching is now supported

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

I've left the original answer unaltered as it was accepted. [/UPDATE]

I've managed to partially get this to work by implementing a Profiled Client Driver (example for Sql Server 2008 below) - this works for simple examples, however I haven't yet found a solution for NH batching (which attempts to cast 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);
    }
}

Solution 2:

I extended Roberts answer above to work with NHibernate batching. There is a lot of code here so it can possibly be shortened, some of it 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; }
}

Solution 3:

Try implementing NHibernate.Connection.IConnectionProvider (you could just inherit DriverConnectionProvider), in GetConnection() wrap the IDbConnection as you need.

Plug your connection provider using the Environment.ConnectionProvider key in your config properties.

Solution 4:

If anyone is interested I have done an integration using a custom Log4net appender instead. This way I feel safe that I don't mess with the Connection object.

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