I have a code-first EF Core codebase running on SqlLite with one entity with about 20 columns and 10 rows. One page requests this entity in code like this:
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}");
I have EF Core logging switched on and I see the query with
Executed DbCommand (2ms) [Parameters=[@email='?'], CommandType='Text', CommandTimeout='30']
However in the logs (even after runnning it multiple times) I see
2018-06-28 15:16:49,442 INFO Controller - User user@domain.com requested entA, in 166,0095
What is happening for the ~160ms that are not spent executing the query?
Update: As suggested by Xanatos I've removed the await and async and luckily I'm seeing more or less the same numbers
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
It would be pretty sad if .net was waiting for 100ms before returning results of a Task
EDIT: I've found out that switching tracking off speeds things up considerably for read-only queries:
_context.ChangeTracker.QueryTrackingBehavior = QueryTrackingBehavior.NoTracking;
You are using await
. There is no strict guarantee that in the instant the data is "ready" the await
continues. If you want to do a measurement, remove await
and change ToListAsync()
in ToList()
. Then we can speak about benchmarks.