1

The duration time for EF queries logged by DbContext.Database.Log differs from the actual duration time that I can see in SQL Server Profiler.

In SQL Server Profile I see a line looking something like this

EventClass       TextData                          Duration 
RPC:Completed    exec sp_executesql N'SELECT...    59473

But nowhere in the DbContext.Database.Logs can I find a query with that duration time. Accoring to those logs, no query took more than a couple of ms.

I've also tried to implement a custom IDbCommandInterceptor that intercepts, times and logs EF queries manually (something like this: https://stackoverflow.com/a/27365855/492067), but I get the same problem there.

What am I missing? Is it something with the actual reading of the data as well?

The EF query in question looks like this:

var duplicates = databaseItems.Where(item => newItems.Contains(item)).ToList();
Community
  • 1
  • 1
Joel
  • 8,502
  • 11
  • 66
  • 115
  • Are you sure that the line you are referring from sql server profiler originates from the dbcontext and not from some other source? – Janne Matikainen Jun 03 '15 at 11:32
  • @JanneMatikainen Pretty sure yeah. I've looked through all the trace logs for the entire lifetime of the application. There is nothing in the logs coming even close to the ~60 seconds duration i see in SQL Server Profiler. – Joel Jun 03 '15 at 11:36
  • How many items in your newsItems collection ? depending on its size, compilation and query plan generation can be horribly slow, will occur on each call.Not sure compilation time appears in DbContext.Database.Log – jbl Jun 03 '15 at 13:17
  • @jbl `newItems` is < 100. Those are the new items I will eventually insert. `databaseItems` is ~ 50 000. – Joel Jun 03 '15 at 13:21
  • How much is the timeout? It could be that SqlClient raises an Exception (so no logs or no log entry you are looking for) but SQL Server continue to work. – bubi Jun 03 '15 at 17:42

0 Answers0