• Home
  • Post
  • Create an Interceptor to find slow queries in EntityFramework Core

Create an Interceptor to find slow queries in EntityFramework Core

In this article we want to create an interceptor to find queries that take more than 2 seconds. To implement, we need to create a class that inherits from the DbCommandInterceptor class. The DbCommandInterceptor class is in EF Core 3 or higher, and you can not use it in EF Core 2.1. To implement, we create a class called DatabaseLongQueryLogger that inherited from DbCommandInterceptor:

public class DatabaseLongQueryLogger : DbCommandInterceptor
{
    private readonly ILogger _logger;
    public DatabaseLongQueryLogger(ILoggerFactory loggerFactory)
    {
        _logger = loggerFactory.CreateLogger(nameof(DatabaseLongQueryLogger));
    }
    public override ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default)
    {
        if (eventData.Duration.TotalMilliseconds > 2)
        {
            LogLongQuery(command, eventData);
        }
        return base.ReaderExecutedAsync(command, eventData, result, cancellationToken);
    }

    private void LogLongQuery(DbCommand command, CommandExecutedEventData eventData)
    {
        _logger.LogWarning($"Long query:{command.CommandText}. TotalMilliseconds:{eventData.Duration.TotalMilliseconds}");
    }

    public override DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
    {
        if (eventData.Duration.TotalMilliseconds > 2000)
        {
            LogLongQuery(command, eventData);
        }
        return base.ReaderExecuted(command, eventData, result);
    }
}

The DbCommandInterceptor class is in the Microsoft.EntityFrameworkCore.Relational package and you must install this package to use it.

The ReaderExecutedAsync method runs when you have read data from the database. (If you use async methods, the ReaderExecutedAsync method will run, and if you use sync methods, the ReaderExecuted method will run)

The value of the Duration property is equal to the amount of time it took for the query to run, and using this property we can find query that have a long time. 

Then when registering the database, we have to introduce this Interceptor created by the AddInterceptors method.

public class Startup
{
    readonly ILoggerFactory loggerFactory = LoggerFactory.Create(builder => { builder.AddConsole(); });

    public Startup(IConfiguration configuration)
    {
        Configuration = configuration;
    }

    public IConfiguration Configuration { get; set; }
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddControllers();
        services.AddDbContext<ApplicationDbContext>(options =>
        {
            options.UseSqlServer(Configuration.GetConnectionString(nameof(ApplicationDbContext)));
            options.AddInterceptors(new DatabaseLongQueryLogger(loggerFactory));// <-- NOTE THIS
        });
    }
    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        app.UseRouting();
        app.UseEndpoints(endpoints =>
        {
            endpoints.MapDefaultControllerRoute();
        });
    }
}

Now if you read data from the database and it takes more than 2 seconds, on the console screen you will see the command and the amount of time elapsed: 

var tags = await _context.Tags.ToListAsync(cancellationToken);

Console screen:

warn: DatabaseLongQueryLogger[0]
      Long query:SELECT [t].[Id], [t].[TagTitle]
      FROM [Tags] AS [t]. TotalMilliseconds:112.9079

The log was created to receive a list of tags from the database and took 112 milliseconds. (I set the logging condition to 2 milliseconds to test) 

if (eventData.Duration.TotalMilliseconds > 2)

;)

Powered by Froala Editor

Posted on Friday, June 18, 2021  |    Author : Farhad Zamani  |  Views : 5232  |  Status : Completed
Tags : EntityFramework Core Logging
Comments