Entity Framework DbCommandInterception for instrumentation.

CommandInterceptionOptions.cs

public class CommandInterceptionOptions
{
    public CommandInterceptionOptions()
    {
        WarningThreshold = TimeSpan.FromSeconds(2);
    }

    public TimeSpan WarningThreshold { get; set; }

    public static CommandInterceptionOptions Default = new CommandInterceptionOptions();
}

DatabaseConfiguration.cs

public class DatabaseConfiguration : DbConfiguration
{
    public DatabaseConfiguration()
    {
        DbInterception.Add(new DbCommandInterceptor());
    }
}

DatabaseContext,cs

public class DatabaseContext : DbContext
{
    static DatabaseContext()
    {
        Database.SetInitializer<DatabaseContext>(null);
        DbConfiguration.SetConfiguration(new DatabaseConfiguration());
    }

    public DatabaseContext(bool autoDetectChangesEnabled = false)
        : base("defaultConnection")
    {
        Configuration.AutoDetectChangesEnabled = autoDetectChangesEnabled;
        Configuration.LazyLoadingEnabled = false;
    }
}

DbCommandInterceptor.cs

public class DbCommandInterceptor : IDbCommandInterceptor
{
    public DbCommandInterceptor(CommandInterceptionOptions options = null)
    {
        _options = options ?? CommandInterceptionOptions.Default;
    }

    public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        OnExecuted(command, interceptionContext);
    }

    public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        OnExecuted(command, interceptionContext);
    }

    public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        OnExecuted(command, interceptionContext);
    }

    public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        OnExecuting(command);
    }

    public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        OnExecuting(command);
    }

    public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        OnExecuting(command);
    }

    private void OnExecuted<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
    {
        DateTime startTime;
        TimeSpan duration = _commandCache.TryRemove(command, out startTime) ? DateTime.Now - startTime : TimeSpan.Zero;

        if (ShouldLog(command, duration, interceptionContext))
            LogMessage(GetLogMessage(command, duration, interceptionContext), duration);
    }

    private void LogMessage(string message, TimeSpan duration)
    {
        if (IsWithinThreshold(duration))
            Trace.TraceInformation(message);
        else
            Trace.TraceWarning(message);
    }

    private bool IsWithinThreshold(TimeSpan duration)
    {
        return duration.CompareTo(_options.WarningThreshold) < 0;
    }

    private bool ShouldLog<T>(DbCommand command, TimeSpan duration, DbCommandInterceptionContext<T> interceptionContext)
    {
        return interceptionContext.Exception != null || !IsWithinThreshold(duration);
    }

    private readonly CommandInterceptionOptions _options;

    private static void OnExecuting(DbCommand command)
    {
        _commandCache.TryAdd(command, DateTime.Now);
    }

    private static string GetLogMessage<T>(DbCommand command, TimeSpan duration, DbCommandInterceptionContext<T> interceptionContext)
    {
        if (interceptionContext.Exception == null)
            return GetLogMessage(command, duration);

        return GetLogMessage(command, duration, interceptionContext.Exception);
    }

    private static string GetLogMessage(DbCommand command, TimeSpan duration, Exception exception)
    {
        const string exceptionMessageFormat = "Database call failed after {0} sec. \r\nCommand:\r\n{1}\r\nError:{2}";
        return string.Format(exceptionMessageFormat, FormatDuration(duration), GetCommandText(command), exception);
    }

    private static string GetLogMessage(DbCommand command, TimeSpan duration)
    {
        const string messageFormat = "Database call took {0} sec. \r\nCommand:\r\n{1}";
        return string.Format(messageFormat, FormatDuration(duration), GetCommandText(command));
    }

    private static string FormatDuration(TimeSpan duration)
    {
        const string format = "N3";
        return duration.TotalSeconds.ToString(format);
    }

    private static string GetCommandText(DbCommand command)
    {
        if (command.Parameters.Count == 0)
            return command.CommandText;

        const string space = " ";
        const string equals = " = ";

        StringBuilder parameters = new StringBuilder();

        for (int i = 0; i < command.Parameters.Count; i++)
        {
            DbParameter param = command.Parameters[i];
            parameters.AppendLine(string.Concat(param.ParameterName, space, param.DbType, equals, param.Value));
        }

        parameters.Append(command.CommandText);

        return parameters.ToString();
    }

    private static readonly ConcurrentDictionary<DbCommand, DateTime> _commandCache = new ConcurrentDictionary<DbCommand, DateTime>();
}

Sample output:

Database call took 0.001 sec.
Command:
select cast(serverproperty('EngineEdition') as int)