0

I'm trying to use IDbInterceptor to time Entity Framework's query executions, as accurately as possible, implementing a variant of Jonathan Allen's answer to a similar question:

public class PerformanceLogDbCommendInterceptor : IDbCommandInterceptor
{
    static readonly ConcurrentDictionary<DbCommand, DateTime> _startTimes =
            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(!_startTimes.TryRemove(command, out startTime))
        {
            //Log exception
            return;
        }
        DateTime now = DateTime.UtcNow;
        duration = now - startTime;

        string requestGUID = Guid.Empty.ToString();
        var context = interceptionContext.DbContexts.SingleOrDefault();
        if (context == null)
        {
            //Log Exception
        }
        else
        {
            var businessContext = context as MyDb;
            if (businessContext == null)
            {
                //Log Exception
            }
            else
            {
                requestGUID = businessContext.RequestGUID.ToString();
            }
        }
        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"
                + $" {duration.TotalMilliseconds.ToString("N3")} ms."
                + $" RequestGUID {requestGUID}"
                //+ $" \r\nCommand:\r\n{parameters.ToString() + command.CommandText}");
        }
        else
        {
            message = string.Format($"EF Database call failed after"
                + $" {duration.TotalMilliseconds.ToString("N3")} ms."
                + $" RequestGUID {requestGUID}"
                + $" \r\nCommand:\r\n{(parameters.ToString() + command.CommandText)}"
                + $"\r\nError:{interceptionContext.Exception} ");
        }
        if (duration == TimeSpan.Zero)
        {
            message += $" \r\nTime: start: {startTime.ToString("hh:mm:ss fffffff")}"
                + $" | now: {now.ToString("hh:mm:ss fffffff")}"
                + $" \r\n \r\nCommand:\r\n"
                + $"{parameters.ToString() + command.CommandText}";
        }
        System.Diagnostics.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)
    {
        _startTimes.TryAdd(command, DateTime.UtcNow);
    }
}

And the weird thing is, that every 10th query or so, it takes 0 ticks to execute. It only seems to happen when I run it asynchronously, with a handful of queries at the same time. Another thing to note, is that when I query the same handful of queries again, it's not always the same queries that take 0 ticks.

Moreover, the database I'm currently testing on, is located on the local network, not the local machine - and the ping time is 0-1ms to it - so even if the data was cached, I can't see how it could take 0 ticks.

On a minor note, most of the queries take suspiciously close to 1, 2 and 3 ms (e.g. 0.997ms to 1.003ms). To me that sounds like the OS rotating thread cpu-time and/or 1ms sleeping. I don't mind that it happens, but I just want to know why, so I can account for the inaccuracies in the results.

It could probably have something to do with the ConcurrentDictionary. But when I'm testing right now, I'm currently only calling an asynchronous (WCF) method once, awaiting every asynchronous DB call, so it shouldn't even fire up more calls at once, to my understanding. This is an example of what is called:

public async Task<IEnumerable<DTJobAPPOverview>> GetJobOverviewAsync()
    ...
    var efResponsibleUserFullName = await dbContext.tblUsers.Where(u =>
                u.UserID == efJob.ResponsibleUserID
            ).Select(u => u.FullName)
            .FirstOrDefaultAsync();
    dtJob.ResponsibleUserName = efResponsibleUserName;
    var efCase = await dbContext.tblCases.FirstOrDefaultAsync(c =>
            c.ID == efJob.FK_CaseID);
    dtJob.Case = Mapper.Map<DTCase>(efCase); //Automapper
    ...
}

By the way, I know that I should probably convert the entire application to use navigation properties, but this is what we have currently, so please bear with me.

Community
  • 1
  • 1
Aske B.
  • 6,419
  • 8
  • 35
  • 62
  • 2
    Don't subtract `DateTime`s to measure time intervals - that's not what it's for. `Stopwatch` is the right class for this, and gives you sub-millisecond precision, unlike `DateTime.UtcNow`. Also, are you sure `DbCommand` has the right kind of identity for your use case? – Luaan Oct 31 '16 at 09:26
  • Events in windows are using the Timer Tick and are queued. When a timer tick occurs Async Events are checked to see if they occurred an if so the data is transferred between processes. So you can have more than one of the same event processed on the same timer tick. – jdweng Oct 31 '16 at 09:27
  • @jdweng I'm not sure what kind of events you're talking about, but asynchronous I/O completion definitely isn't in any way synchronized with a timer tick (though obviously, the callbacks do require a thread which might take some time), and there definitely isn't a mechanism where every timer tick all the asynchronous events are checked to see if they occurred. You can have millions of pending asynchronous operations and it won't take a single CPU instruction until they actually get signalled. – Luaan Oct 31 '16 at 09:31
  • Luaan : Where does the signalling get checked? It is the timer event that checks the status of the registered signals. – jdweng Oct 31 '16 at 09:48

1 Answers1

1

Kudos to your network admin - it's quite rare to see a network with such low latencies.

DateTime.UtcNow has a resolution that's the same as the system timer (hardly surprising, since the system timer updates the current time :)). By default, on Windows NT, this is 10ms - so on a clean system, you only get an accuracy of 10ms. A value of 10ms may mean the operation took no time at all, or that it took 9.9ms, or that it took 19.9ms, depending on your luck.

On your system, either some application changed the timer frequency (Chrome and other animation-heavy applications are frequent abusers), or you're running onw Windows 8+, which moved to a tickless timer system. In any case, your timer accuracy is 1ms - and that's what you're seeing in your logs.

If you want a higher precision/accuracy, you'll need to use Stopwatch. DateTime isn't designed for what you're using it for anyway, though it often works well enough as long as you don't rely on it too much (DST/leap seconds are so much fun :)). Stopwatch is.

Finally, make sure that your dictionary's keys work the way you assume they do. Are you sure those DbCommands have the kind of identity you require? It's not like there's a contractual requirement for DbCommand to have reference identity, or for EntityFramework not to reuse DbCommand instances.

Luaan
  • 62,244
  • 7
  • 97
  • 116
  • Converting to `Stopwatch` definitely seems to give more credible results. I completely forgot about that class. I'm not 100% sure about using the `DbCommand` to identify a query with, but it seems to be working thus far. Since it's not guaranteed by EntityFramework, I definitely see the potential issues of depending on it. Unfortunately, I don't have any bright ideas for alternatives. – Aske B. Oct 31 '16 at 10:39
  • Regardless, comparing with `Database.Log = m => System.Diagnostics.Debug.Write(m);`, it seems that there's an added delay of up to 3 ms in the `IDbInterceptor` pipeline and/or network, assuming `-- Completed in ## ms with result: SqlDataReader` is the actual execution time returned by the database. So far it seems the only alternative is to substring the default log message, which I'm not too happy about. Thanks again for the help. – Aske B. Oct 31 '16 at 11:37
  • How do you actually convert the code to use `Stopwatch`? – Oskar Feb 09 '18 at 14:21
  • Nevermind, I found the actual EF6 implementation that uses `Stopwatch`: https://github.com/aspnet/EntityFramework6/blob/master/src/EntityFramework/Infrastructure/Interception/DatabaseLogFormatter.cs – Oskar Feb 12 '18 at 06:49