Entity Framework 6 - Запросы синхронизации

Ответ 1

Вот регистратор, который я обычно использую для EF.

public class EFLoggerForTesting : IDbCommandInterceptor
{
    static readonly ConcurrentDictionary<DbCommand, DateTime> m_StartTime = new ConcurrentDictionary<DbCommand, DateTime>();

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

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

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

    private static void Log<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
    {
        DateTime startTime;
        TimeSpan duration;

        m_StartTime.TryRemove(command, out startTime);
        if (startTime != default(DateTime))
        {
            duration = DateTime.Now - startTime;
        }
        else
            duration = TimeSpan.Zero;

        var requestId =-1;
        string message;

        var parameters = new StringBuilder();
        foreach (DbParameter param in command.Parameters)
        {
            parameters.AppendLine(param.ParameterName + " " + param.DbType + " = " + param.Value);
        }

        if (interceptionContext.Exception == null)
        {
            message = string.Format("Database call took {0} sec. RequestId {1} \r\nCommand:\r\n{2}", duration.TotalSeconds.ToString("N3"), requestId, parameters.ToString() + command.CommandText);
        }
        else
        {
            message = string.Format("EF Database call failed after {0} sec. RequestId {1} \r\nCommand:\r\n{2}\r\nError:{3} ", duration.TotalSeconds.ToString("N3"), requestId, parameters.ToString() + command.CommandText, interceptionContext.Exception);
        }

        Debug.WriteLine(message);
    }


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

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

    public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        OnStart(command);
    }
    private static void OnStart(DbCommand command)
    {
        m_StartTime.TryAdd(command, DateTime.Now);
    }
}

К сожалению, документации не существует, поэтому я не знаю, будет ли это работать для вашего сценария.

Ответ 2

Если вы работаете в веб-приложении, вы можете попробовать Glimpse: http://getglimpse.com/. В противном случае попробуйте MiniProfiler: http://miniprofiler.com/.

Ответ 3

Как говорит @Ricardo Перес, Glimpse хорош для этого. Он поставляется с плагином Glimpse.Ado, который может использоваться для легкого профилирования любого DbConnection, который является основным классом для расширения.

Ручная точка интеграции для ADO в Glimpse заключается в том, чтобы обернуть DbConnection в GlimpseDbConnection, как видно из этого сообщения в блоге: http://getglimpse.com/Docs/Manual-ADO-Integration. Другие поставщики, такие как EF, автоматически интегрируются с пакетом Glimpse.Ef.

Если вы все еще решите, что хотите добиться этого вручную, я бы предложил обернуть DbConneciton самостоятельно и использовать это вместо обычного DbConnection. Вы можете получить простые тайминги, делая это.

Вы можете видеть, как Glimpse делает это на своем github: https://github.com/Glimpse/Glimpse/tree/master/source/Glimpse.Ado/AlternateType

В качестве альтернативы всегда есть возможность добавить этот вид ведения журнала на уровне репозитория или на уровне метода в зависимости от того, сколько журналов вам нужно.

Ответ 4

Скорее упрощен, но вы не можете использовать объект System.Timers.Timer? Вызов начинается непосредственно перед кодом EF и заканчивается сразу после кода EF. Если у вас есть асинхронный код, вы можете позвонить .Result и удалить ожидания, чтобы запустить код синхронно и время вызовов. В дополнение к этому, если вы используете профилировщик SQL и вычитаете одно значение из другого (Timer-Profiler), вы получите представление о том, как долго выполняется код EF для выполнения.

Ответ 5

Ниже приведена моя упрощенная версия оригинала DatabaseLogFormatter. Главное отличие состоит в том, что в этом нет фильтрации, и я не регистрирую фактический SQL-запрос или его параметры (поскольку меня интересуют только временные запросы). Он регистрируется, когда он открыл соединение, выполнил запрос и снова закрыл соединение. Поскольку @aske-b заметил выше, используя DateTime (как принято в ответе), это не очень точно.

public class CustomDatabaseLogFormatter : IDbCommandInterceptor, IDbConnectionInterceptor
{
    private readonly Action<string> _writeAction;
    private readonly Stopwatch _stopwatch = new Stopwatch();

    /// <summary>
    /// Creates a formatter that will log every command from any context and also commands that do not originate from a context.
    /// </summary>
    /// <remarks>
    /// This constructor is not used when a delegate is set on <see cref="Database.Log" />. Instead it can be
    /// used by setting the formatter directly using <see cref="DbInterception.Add" />.
    /// </remarks>
    /// <param name="writeAction">The delegate to which output will be sent.</param>
    public CustomDatabaseLogFormatter(Action<string> writeAction)
    {
        Check.NotNull(writeAction, "writeAction");

        _writeAction = writeAction;
    }

    internal Action<string> WriteAction
    {
        get { return _writeAction; }
    }

    /// <summary>
    /// Writes the given string to the underlying write delegate.
    /// </summary>
    /// <param name="output">The string to write.</param>
    protected virtual void Write(string output)
    {
        _writeAction(output);
    }

    /// <summary>
    /// The stopwatch used to time executions. This stopwatch is started at the end of
    /// <see cref="NonQueryExecuting" />, <see cref="ScalarExecuting" />, and <see cref="ReaderExecuting" />
    /// methods and is stopped at the beginning of the <see cref="NonQueryExecuted" />, <see cref="ScalarExecuted" />,
    /// and <see cref="ReaderExecuted" /> methods. If these methods are overridden and the stopwatch is being used
    /// then the overrides should either call the base method or start/stop the stopwatch themselves.
    /// </summary>
    /// <returns>The stopwatch.</returns>
    protected internal Stopwatch Stopwatch
    {
        get { return _stopwatch; }
    }

    private void RestartStopwatch()
    {
        Stopwatch.Restart();
    }

    private void StopStopwatch()
    {
        Stopwatch.Stop();
    }

    #region IDbCommandInterceptor
    /// <summary>
    /// This method is called before a call to <see cref="DbCommand.ExecuteNonQuery" /> or
    /// one of its async counterparts is made.
    /// Starts the stopwatch returned from <see cref="Stopwatch"/>.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        RestartStopwatch();
    }

    /// <summary>
    /// This method is called after a call to <see cref="DbCommand.ExecuteNonQuery" /> or
    /// one of its async counterparts is made.
    /// Stops the stopwatch returned from <see cref="Stopwatch"/> and calls <see cref="Executed" />.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        StopStopwatch();
        Executed(command, interceptionContext);
    }

    /// <summary>
    /// This method is called before a call to <see cref="DbCommand.ExecuteReader(CommandBehavior)" /> or
    /// one of its async counterparts is made.
    /// Starts the stopwatch returned from <see cref="Stopwatch"/>.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        RestartStopwatch();
    }

    /// <summary>
    /// This method is called after a call to <see cref="DbCommand.ExecuteReader(CommandBehavior)" /> or
    /// one of its async counterparts is made.
    /// Stops the stopwatch returned from <see cref="Stopwatch"/> and calls <see cref="Executed" />.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        StopStopwatch();
        Executed(command, interceptionContext);
    }

    /// <summary>
    /// This method is called before a call to <see cref="DbCommand.ExecuteScalar" />  or
    /// one of its async counterparts is made.
    /// Starts the stopwatch returned from <see cref="Stopwatch"/>.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        RestartStopwatch();
    }

    /// <summary>
    /// This method is called after a call to <see cref="DbCommand.ExecuteScalar" />  or
    /// one of its async counterparts is made.
    /// Stops the stopwatch returned from <see cref="Stopwatch"/> and calls
    /// <see cref="Executed" />.
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public virtual void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        StopStopwatch();
        Executed(command, interceptionContext);
    }

    /// <summary>
    /// Called whenever a command has completed executing. Calls <see cref="LogResult" />.
    /// </summary>
    /// <typeparam name="TResult">The type of the operation results.</typeparam>
    /// <param name="command">The command that was executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the command.</param>
    public virtual void Executed<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        LogResult(command, interceptionContext);
    }

    /// <summary>
    /// Called to log the result of executing a command.
    /// </summary>
    /// <typeparam name="TResult">The type of the operation results.</typeparam>
    /// <param name="command">The command being logged.</param>
    /// <param name="interceptionContext">Contextual information associated with the command.</param>
    public virtual void LogResult<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Check.NotNull(command, "command");
        Check.NotNull(interceptionContext, "interceptionContext");

        var stopwatch = Stopwatch;

        if (interceptionContext.Exception != null)
        {
            Write(
                String.Format(StringResources.CommandLogFailed, stopwatch.ElapsedMilliseconds, interceptionContext.Exception.Message)
                );
        }
        else if (interceptionContext.TaskStatus.HasFlag(TaskStatus.Canceled))
        {
            Write(String.Format(StringResources.CommandLogCanceled, stopwatch.ElapsedMilliseconds));
        }
        else
        {
            var result = interceptionContext.Result;
            var resultString = (object)result == null
                ? "null"
                : (result is DbDataReader)
                    ? result.GetType().Name
                    : result.ToString();
            Write(String.Format(StringResources.CommandLogComplete, stopwatch.ElapsedMilliseconds, resultString));
        }
    }
    #endregion

    #region IDbConnectionInterceptor
    public void BeginningTransaction(DbConnection connection, BeginTransactionInterceptionContext interceptionContext)
    { }

    public void BeganTransaction(DbConnection connection, BeginTransactionInterceptionContext interceptionContext)
    { }

    public void Closing(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    { }

    /// <summary>
    /// Called after <see cref="DbConnection.Close" /> is invoked.
    /// </summary>
    /// <param name="connection">The connection that was closed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public void Closed(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    {
        Check.NotNull(connection, "connection");
        Check.NotNull(interceptionContext, "interceptionContext");

        if (interceptionContext.Exception != null)
        {
            Write(String.Format(StringResources.ConnectionCloseErrorLog, DateTimeOffset.UtcNow, interceptionContext.Exception.Message));
        }
        else
        {
            Write(String.Format(StringResources.ConnectionClosedLog, DateTimeOffset.UtcNow));
        }
    }

    public void ConnectionStringGetting(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void ConnectionStringGot(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void ConnectionStringSetting(DbConnection connection, DbConnectionPropertyInterceptionContext<string> interceptionContext)
    { }

    public void ConnectionStringSet(DbConnection connection, DbConnectionPropertyInterceptionContext<string> interceptionContext)
    { }

    public void ConnectionTimeoutGetting(DbConnection connection, DbConnectionInterceptionContext<int> interceptionContext)
    { }

    public void ConnectionTimeoutGot(DbConnection connection, DbConnectionInterceptionContext<int> interceptionContext)
    { }

    public void DatabaseGetting(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void DatabaseGot(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void DataSourceGetting(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void DataSourceGot(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void Disposing(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    { }

    public void Disposed(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    { }

    public void EnlistingTransaction(DbConnection connection, EnlistTransactionInterceptionContext interceptionContext)
    { }

    public void EnlistedTransaction(DbConnection connection, EnlistTransactionInterceptionContext interceptionContext)
    { }

    public void Opening(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    { }

    /// <summary>
    /// Called after <see cref="DbConnection.Open" /> or its async counterpart is invoked.
    /// </summary>
    /// <param name="connection">The connection that was opened.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.</param>
    public void Opened(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    {
        Check.NotNull(connection, "connection");
        Check.NotNull(interceptionContext, "interceptionContext");

        if (interceptionContext.Exception != null)
        {
            Write(
                interceptionContext.IsAsync
                    ? String.Format(StringResources.ConnectionOpenErrorLogAsync,
                        DateTimeOffset.UtcNow, interceptionContext.Exception.Message)
                    : String.Format(StringResources.ConnectionOpenErrorLog, DateTimeOffset.UtcNow, interceptionContext.Exception.Message));
        }
        else if (interceptionContext.TaskStatus.HasFlag(TaskStatus.Canceled))
        {
            Write(String.Format(StringResources.ConnectionOpenCanceledLog, DateTimeOffset.UtcNow));
        }
        else
        {
            Write(
                interceptionContext.IsAsync
                    ? String.Format(StringResources.ConnectionOpenedLogAsync, DateTimeOffset.UtcNow)
                    : String.Format(StringResources.ConnectionOpenedLog, DateTimeOffset.UtcNow));
        }
    }

    public void ServerVersionGetting(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void ServerVersionGot(DbConnection connection, DbConnectionInterceptionContext<string> interceptionContext)
    { }

    public void StateGetting(DbConnection connection, DbConnectionInterceptionContext<ConnectionState> interceptionContext)
    { }

    public void StateGot(DbConnection connection, DbConnectionInterceptionContext<ConnectionState> interceptionContext)
    { } 
    #endregion
}

internal class Check
{
    public static T NotNull<T>(T value, string parameterName)
        where T : class
    {
        if (value == null)
        {
            throw new ArgumentNullException(parameterName);
        }

        return value;
    }
}

StringResources.resx:
CommandLogCanceled          Canceled in {0} ms{1}
CommandLogComplete          Completed in {0} ms with result: {1}
CommandLogFailed            Failed in {0} ms with error: {1}
ConnectionClosedLog         Closed connection at {0}
ConnectionCloseErrorLog     Failed to close connection at {0} with error: {1}
ConnectionOpenCanceledLog   Cancelled open connection at {0}
ConnectionOpenedLog         Opened connection at {0}
ConnectionOpenedLogAsync    Opened connection asynchronously at {0}
ConnectionOpenErrorLog      Failed to open connection at {0} with error: {1}
ConnectionOpenErrorLogAsync Failed to open connection asynchronously at {0} with error: {1}