Entity Framework 6 - Timing queries

问题:

I am using Entity Framework 6 and it's awesome database interceptor features to log queries which are being sent from application the database. However, I am struggling to time those queries, I have a long running query which returns hundred of thousands to millions of rows so it takes around 6 to 15 seconds depending on the amount of data this query is going to return. Entity framework is returning a SqlDataReader because of which I cannot get the exact time it takes to get the result. I want to know the complete execution time from the time query was sent to the time last row was read. Is there a way I can do it.

回答1:

Here is the logger I usually use for 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;


        if (m_StartTime.TryRemove(command, out startTime))
        {
            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);
    }
}

Unfortunately the documentation is non-existent so I don't know if this will work for your scenario.

回答2:

If you are working in a web application, you can try Glimpse: http://getglimpse.com/. Otherwise, try MiniProfiler: http://miniprofiler.com/.

回答3:

As @Ricardo Peres answer suggests, Glimpse is good for this. It comes with the Glimpse.Ado plugin that can be used to easily profile any DbConnection, which is the main class to extend here.

The manual integration point for ADO in Glimpse is to wrap the DbConnection in a GlimpseDbConnection, as can be seen in this blog post: http://getglimpse.com/Docs/Manual-ADO-Integration. Other providers like EF are automatically integrated with the Glimpse.Ef package.

If you still decide you want to achieve this manually, I would suggest wrapping DbConneciton yourself and using this in-place of the regular DbConnection. You could get simple timings doing this.

You can see how Glimpse do it on their github: https://github.com/Glimpse/Glimpse/tree/master/source/Glimpse.Ado/AlternateType

Alternatively, there is always the option to add this sort of logging at the repository level or at the method level depending on how much logging you need.

回答4:

You can try the example explained here

In this example, we are starting a Stopwatch when a command starts executing and we stop the Stopwatch when the command is completed, this way we can identify the slow queries and log them.

public class SqlMonitorInterceptor : IDbCommandInterceptor
{
    private static readonly ILog logger = LogManager.GetCurrentClassLogger();
    private static readonly int sqlWarningThresholdMs = int.Parse(ConfigurationManager.AppSettings["sqlPerformance_warningThresholdMilliseconds"]);
    private readonly Stopwatch _stopwatch = new Stopwatch();

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

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

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

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

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

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

    private void CommandExecuting() {
        _stopwatch.Restart();
    }

    private void CommandExecuted<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        _stopwatch.Stop();
        LogIfError(command, interceptionContext);
        LogIfTooSlow(command, _stopwatch.Elapsed);
    }

    private void LogIfError<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        if (interceptionContext.Exception != null)
        {
            logger.ErrorFormat("Command {0} failed with exception {1}",
                command.CommandText, interceptionContext.Exception);
        }
    }

    private void LogIfTooSlow(DbCommand command, TimeSpan completionTime)
    {
        if (completionTime.TotalMilliseconds > sqlWarningThresholdMs)
        {
            logger.WarnFormat("Query time ({0}ms) exceeded the threshold of {1}ms. Command: \"{2}\"",
                completionTime.TotalMilliseconds, sqlWarningThresholdMs, command.CommandText);
        }
    }
}

回答5:

Below is my simplified version of the original DatabaseLogFormatter. The main difference is that there is no filtering in this one and I don't log the actual SQL query or it's parameters (since I'm only interested in timing the queries). It log when it has opened a connection, executed a query and when it closed the connection again. As @aske-b noticed above using DateTime (as the accepted answer does) just isn't very accurate.

---

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's 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's 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}

回答6:

Rather simplistic, but couldn't you use a System.Timers.Timer object? Call start just before the EF code and call end just after the EF code. If you have async code in there you could call .Result and remove the awaits in order to run the code synchronously and time the calls. In addition to this if you use the SQL profiler and subtract one value from the other (Timer - Profiler) you will get an idea of how long the EF code is taking to execute.