c# - How can it take 0 ticks to query the database asynchronously?

Question

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}"
                //+ $" 
Command:
{parameters.ToString() + command.CommandText}");
        }
        else
        {
            message = string.Format($"EF Database call failed after"
                + $" {duration.TotalMilliseconds.ToString("N3")} ms."
                + $" RequestGUID {requestGUID}"
                + $" 
Command:
{(parameters.ToString() + command.CommandText)}"
                + $"
Error:{interceptionContext.Exception} ");
        }
        if (duration == TimeSpan.Zero)
        {
            message += $" 
Time: start: {startTime.ToString("hh:mm:ss fffffff")}"
                + $" | now: {now.ToString("hh:mm:ss fffffff")}"
                + $" 
 
Command:
"
                + $"{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.

Answer 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.