EF Core накладные расходы?

Question

У меня есть кодовая база EF Core, работающая в первую очередь на SqlLite, с одним объектом с 20 столбцами и 10 строками. Одна страница запрашивает эту сущность в коде, подобном этому:

var start = DateTime.Now;
var entA = await _context.entA.FromSql("SELECT * FROM entA "+
    "where (Name like '%_Demo' or EXISTS(SELECT NULL FROM entB WHERE StudyId = entA.ID and email = @email)) AND IsDeleted = 0 "+
    "order by colC COLLATE NOCASE",
            new SqliteParameter("@email", User.Identity.Name)) 
    .ToListAsync();
log.Info($"User {User.Identity.Name} requested entA, in {DateTime.Now.Subtract(start).TotalMilliseconds}");

У меня включено ведение журнала EF Core, и я вижу запрос с

Executed DbCommand (2ms) [Parameters=[@email='?'], CommandType='Text', CommandTimeout='30']

Однако в логах (даже после запуска несколько раз) я вижу

2018-06-28 15:16:49,442 INFO Controller - User user@domain.com requested entA, in 166,0095 

Что происходит с ~ 160 мс, которые не были потрачены на выполнение запроса?

Обновление: по предложению Xanatos я удалил await и async и, к счастью, я вижу более или менее одинаковые цифры

INFO Controller - User user@domain.com requested entA, in 207,0118 
INFO Controller - User user@domain.com requested entA, in 164,0094 
INFO Controller - User user@domain.com requested entA, in 225,0129 
INFO Controller - User user@domain.com requested entA, in 180,0103 

Было бы очень грустно, если .net ждал 100 мс, прежде чем возвращать результаты задачи

РЕДАКТИРОВАТЬ: я обнаружил, что отключение отслеживания значительно ускоряет запросы только для чтения:

_context.ChangeTracker.QueryTrackingBehavior = QueryTrackingBehavior.NoTracking;

Answer 1

Вы используете await. Нет строгой гарантии, что в момент, когда данные «готовы», await продолжается. Если вы хотите выполнить измерение, удалите await и измените ToListAsync() на ToList(). Тогда мы можем говорить о контрольных показателях.