Как сделать так, чтобы асинхронно запрашивать базу данных с помощью 0 тиков?

Question

Я пытаюсь использовать IDbInterceptor расстрелов время запроса Entity Framework, в как можно более точно, реализуя вариант answer to a similar questionJonathan Allen «s:

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); 
    } 
} 

И странно то, что каждый 10-запроса или около того, для выполнения требуется 0 тиков. Кажется, это происходит, когда я запускаю ее асинхронно, одновременно с несколькими запросами. Еще одна вещь, которую следует отметить, заключается в том, что когда я снова запрашиваю ту же самую часть запросов, это не всегда те же запросы, что и 0 тиков.

Кроме того, база данных, в которой я сейчас тестирую, находится в локальной сети, а не на локальной машине, а время ping равно 0-1ms, поэтому даже если данные были кэшированы, я не могу посмотреть, как это может занять 0 тиков.

На незначительном примечании большинство запросов подозрительно близки к 1, 2 и 3 мс (например, от 0,997 мс до 1,003 мс). Для меня это звучит как вращающийся поток ОС спящего времени и/или 1 мс спать. Я не возражаю, что это происходит, но я просто хочу знать, почему, поэтому я могу объяснить неточности в результатах.

Возможно, это как-то связано с ConcurrentDictionary. Но когда я тестирую прямо сейчас, я в настоящее время вызываю только асинхронный (WCF) метод, ожидающий каждого асинхронного вызова БД, поэтому мне не нужно даже запускать больше вызовов сразу, насколько я понимаю. Это пример того, что называется:

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

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

Answer 1

Претензии к вашему администратору сети - довольно редко видеть сеть с такими низкими задержками.

DateTime.UtcNow имеет разрешение, аналогичное системному таймеру (вряд ли удивительно, поскольку системный таймер обновляет текущее время :)). По умолчанию в Windows NT это составляет 10 мс - поэтому в чистой системе вы получаете только 10 мс. Значение 10 мс может означать, что операция не заняла времени вообще, или что она заняла 9,9 мс, или что она заняла 19,9 мс, в зависимости от вашей удачи.

В вашей системе какое-либо приложение изменило частоту таймера (Chrome и другие приложения, интенсивно использующие анимацию, являются частыми злоупотреблениями), или вы запускаете Windows 8+, которая перемещается в систему без тикового таймера. В любом случае точность таймера составляет 1 мс - и это то, что вы видите в своих журналах.

Если вам нужна более высокая точность/точность, вам необходимо использовать Stopwatch. DateTime не предназначен для использования в любом случае, хотя он часто работает достаточно хорошо, если вы не слишком полагаетесь на него (DST/прыжки секунд так весело :)). Stopwatch есть.

Наконец, убедитесь, что ключи вашего словаря работают так, как вы предполагаете. Вы уверены, что у этих DbCommand s есть личный идентификатор, который вам нужен? Это не похоже на контрактное требование для DbCommand, чтобы иметь ссылочный идентификатор, или для EntityFramework не использовать повторно DbCommand экземпляров.