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();
5
  • Are you sure that the line you are referring from sql server profiler originates from the dbcontext and not from some other source? Jun 3, 2015 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 3, 2015 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 3, 2015 at 13:17
  • @jbl newItems is < 100. Those are the new items I will eventually insert. databaseItems is ~ 50 000.
    – Joel
    Jun 3, 2015 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 3, 2015 at 17:42

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.