Loggning av SQL-statements i Entity Framework och EF Core

Vid ett antal tillfällen har man stött på prestandaproblem och andra konstigheter vid användning Entity Framework där misstankarna riktas mot det genererade SQL-uttrycket. Ett sätt att se vad som händer är att profilera databasen, men ibland så har man inte den möjligheten på grund av till exempel rättighetsproblem. Då finns det istället möjlighet att få ut SQL-frågan genom att konfigurera loggning från ramverket.

Nedan följer exempel för Entity Framework 6 och för EF Core 2 hur detta konfigureras.
Komplett källkod för exemplen återfinns här https://github.com/HeadlightAB/LoggingSQLGeneratedByEF.

Entity Framework (6.2.0)

För att konfigurera loggning av SQL-statements, lägg till Database.Log = ... i din context enligt nedan:

public class MyContext : DbContext  
{
    ...
    public MyContext()
    {
        ...
        Database.Log = s => Debug.Write(s);
        ...
    }
}

Gör en select enligt

var ctx = new MyContext();  
var cars = ctx.Cars.Select(x => x.Brand).ToArray();  

och i Debug-output få man följande loggning:

...
Opened connection at 2019-05-06 12:47:20 +02:00  
SELECT  
    [Extent1].[Brand] AS [Brand]
    FROM [dbo].[Cars] AS [Extent1]
-- Executing at 2019-05-06 12:47:20 +02:00
-- Completed in 0 ms with result: SqlDataReader
...

Komplett källkod för projektet https://github.com/HeadlightAB/LoggingSQLGeneratedByEF/tree/master/FullFrameworkConsoleApp

EF Core (2.2.4)

Console application, .NET Core

Lösningen i EF Core ser ungefär likadan ut som för Entity Framework men man konfigurerar loggningen i OnConfiguring-metoden istället:

public class MyContext : DbContext  
{
    ...
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        optionsBuilder
            .UseSqlServer(
                @"Server=(localdb)\MSSQLLocalDB;Database=CoreConsoleApp.MyContext;Trusted_Connection=True;")
            .UseLoggerFactory(
                new LoggerFactory(new[] {new DebugLoggerProvider((s, level) => true)}));
    }
    ...
}
...

En liknande select-fråga ger då följande loggning i Debug-output:

...
Microsoft.EntityFrameworkCore.Database.Command:Debug: Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']  
SELECT [x].[Brand]  
FROM [Cars] AS [x]  
Microsoft.EntityFrameworkCore.Database.Command:Information: Executed DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='30']  
SELECT [x].[Brand]  
FROM [Cars] AS [x]  
Microsoft.EntityFrameworkCore.Database.Command:Debug: A data reader was disposed.  
...

Komplett källkod för projektet https://github.com/HeadlightAB/LoggingSQLGeneratedByEF/tree/master/CoreConsoleApp

ASP.NET Web application, .NET Core

Det här exemplet påvisar hur man kan konfigurera loggning om man använder sig av .NET Cores inbyggda IoC-container och konfigurering av DbContext via den. Det är lite trix att få tag på en context-instans i Program.cs, men det utelämnas här och istället fokuserar vi på ConfigureServices i Startup.cs:

...
public void ConfigureServices(IServiceCollection services)  
{
   ...
   services.AddDbContext<MyContext>(options => 
      options
        .UseSqlServer(@"Server=(localdb)\MSSQLLocalDB;Database=CoreWebApi.MyContext;Trusted_Connection=True;")
        .UseLoggerFactory(new LoggerFactory(new []{new DebugLoggerProvider()})));
    ...
}
...

Komplett källkod för projektet https://github.com/HeadlightAB/LoggingSQLGeneratedByEF/tree/master/CoreWebApi

Jämför man med överlagringen av OnConfiguring i Console-app-exemplet ovan så är ser vi att själva loggningskonfiguration är helt identisk sånär som på att i Console-app-exemplet används filter-funktionsvarianten av DebugLoggerProvider-konstruktorn. Denna kommer att plockas bort i kommande version av .NET Core.