5

To measure and debug the times for each query in Entity Framework 6.3, I implemented a DbCommandInterceptor, as per the accepted answer to a related question:

public class EFLogger : IDbCommandInterceptor
{
    public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        startMeasuring(command, interceptionContext);
    }

    public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        stopMeasuring(command, interceptionContext);
    }
    ...
}

DbInterception.Add(new EFLogger());

This works fine, it is called before and after each command is sent to the database, and I can measure the time it took.

However, it only measures the time until the SqlDataReader is initialized. Most of the time for each query is is spend while the SqlDataReader is iterated and consumed. I want to find out how long this takes for each query, ideally without adding stopwatch code for every statement.

Can I somehow intercept when the SqlDataReader is closed or the 'final' record is read?

I realize that the SqlDataReader might not always be consumed entirely, so the final record could be hard to detect. For now, I am only interested in cases where the SqlDataReader is iterated until the end.

It seems like the IDbCommandInterceptor interface does not provide any events for that.

Is there any other mechanism for capturing the moment when the reader is closed?

Or could I inject a custom DbDataReader wrapper into the Entity Framework code? Or is there an alternative approach from the SQL Server side?

HugoRune
  • 13,157
  • 7
  • 69
  • 144
  • That proposed duplicate is the specific question where I got the inspiration for this IDbCommandInterceptor, as mentioned above. But like i said, the accepted answer fails to measure the time spent consuming the SqlDataReader. – HugoRune Sep 25 '19 at 15:06
  • have you tried to implement IDbConnectionInterceptor as well? If you add logging to its Closing I think it will include the time needed for SqlDataReader to iterate. – michal.jakubeczy Oct 01 '19 at 14:48

1 Answers1

3

You can output log to console context.Database.Log = Console.Write see https://learn.microsoft.com/en-us/ef/ef6/fundamentals/logging-and-interception for more information.

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write; // set Database.Log property inside dbContex constructor to log all queries
    //your query here
}

this will output every query with parameters passed and time it took to execute the query.

Arjun Vachhani
  • 1,761
  • 3
  • 21
  • 44
  • I tried that, I am fairly certain it only measures the time until the sqldatareader is opened, not until the data has been transferred. It shows the same times as the dbcommandinterceptor, and the console output is shown a long time before the next line is executed. – HugoRune Oct 04 '19 at 10:22
  • ok, if you are not returning huge dataset then time to read and create objects would be small – Arjun Vachhani Oct 04 '19 at 10:25