EF Core Query Tags and Alternatives

UPDATE: Upgraded samples to EF Core 5. (you can find old sample code in this branch)

When doing a performance review on client applications (and my friend's apps), I often see issues related to EF Core and most devs don't seem to notice them until they spiral out of control. When this happens, they don't know how to find problematic queries and then link them back to the original code.

In this blog post, I'll show you a couple of tricks on how to track your queries, so when you need to debug performance issues, you won't have a problem finding the problematic SQL query as well the code that generates it. You can also skip to the end of the recommended approach.

I'll assume that you have configured logging in your .NET Core application, but if you need instructions for that, go to ASP.NET Core 3.0 + Serilog. I recommend collecting the logs into Seq and/or Application Insights for later analysis.

Tagging Queries

If you use EF Core 2.2+, you can easily track your queries by tagging them with .TagWith().

var list = await _context.Tweets
    .TagWith("GetTweets")
    .ToListAsync(cancellationToken)
    .ConfigureAwait(false);

This will add GetTweets into SQL statement, which can be seen in logs and even SQL Profiler.

-- GetTweets

SELECT [t].[Id], [t].[CreatedUtc], [t].[Message], [t].[Username]
FROM [Tweets] AS [t]

Figure: We can see the tag as part of the query.

Query Tags are supported to any IQueryable<T>. This includes methods like FromSqlRaw which are now being used to execute store procedures and views as long it inherits from IQueryable<T>.

Sadly adding, updating and removing entities is not supported by Query Tags.

NOTE: For EF6 you can try to use this 3rd party Nuget package: EF6.TagWith

Log Scope

The second approach is to add Log Scope. This approach is great if .TagWith() isn't available. This could be because you want to log inserts/updates/deletes, you're running EF Core before version 2.2, legacy EF or even if you don't have direct access to the queries (like Microsoft Identity).

using (_logger.BeginScope(new Dictionary<string, object> { { "EFQueries", "GetTweets" } }))
{
    return await _context.Tweets
        .ToListAsync(ct)
        .ConfigureAwait(false);
}

In this example, I'll show you how you can indirectly log SQL statements generated by EF Core. To demonstrate that, we'll need to get an instance of ILogger and then we'll create a new Log Scope, which propagates to all logs inside that context.

public async Task InsertTweet(string username, string message, CancellationToken ct = default)
{
    // This can optionally be in the bellow log scope but is not necessary.
    // The tweet is going to be added into SQL DB when `.SaveChanges` is called.
    _context.Tweets.Add(new Tweet
    {
        Username = username,
        Message = message
    });
    
    using (_logger.BeginScope(new Dictionary<string, object> { { "EFQueries", "InsertTweet" } }))
    {
        // This will make SQL queries to save data into DB.
        await _context.SaveChangesAsync(ct).ConfigureAwait(false);
    }
}

Figure: Add tweet by adding it to Tweets table.

public async Task InsertTweet(string username, string message, CancellationToken ct = default)
{
    using (_logger.BeginScope(new Dictionary<string, object> { { "EFQueries", "InsertTweetStoreProc" } }))
    {
        InsertTweetInternal(username, message);
    }
}

private async Task InsertTweetInternal(string username, string message)
{
    // This query can also be outside this class and it would still be logged with the "EFQueries" scope. (EF Core 5 example)
    _ = await _context.Database
        .ExecuteSqlRawAsync(
            "InsertTweet @Username, @Message",
            new SqlParameter("Username", username),
            new SqlParameter("Message", message));
}

Figure: Insert Tweets with store procedure.

The above query might get lost if you have a lot of different queries, but by adding a Log Scope, we can search in your preferred rich logger aggregator like Seq or Application Insights for "InsertTweetStoreProc" in property "EFQueries".

This way, all queries are searchable based on context, find rogue queries and separate your queries from 3rd party queries. Now you can better focus on what queries to optimize or find original code that ran that query.

Recommended approach

Depending on the project, Log Scope might be a better approach since now you can track every SQL query (and other logs) the same way. Use Log Scopes when you know that SQL Server is going to be a problem or visibility is more critical then compact code.

using (_logger.EFQueryScope("GetTweetsLog"))
{
    return await _context.Tweets
        .TagWith("GetTweets + LogContext")
        .ToListAsync(ct)
        .ConfigureAwait(false);
}

Small utility for easier logging:

public static class EFCoreLoggingUtils
{
    public static IDisposable EFQueryScope<T>(this ILogger<T> logger, string queryScopeName)
    {
        return logger.BeginScope(new Dictionary<string, object> { { "EFQueries", queryScopeName } });
    }

    public static IDisposable EFQueryScope(this ILogger logger, string queryScopeName)
    {
        return logger.BeginScope(new Dictionary<string, object> { { "EFQueries", queryScopeName } });
    }
}

In Seq and Application Insights you can find all queries with the following filter SourceContext = "Microsoft.EntityFrameworkCore.Database.Command". You can then do further filtering based on Log Scope by filtering EFQueries.

You can find source code here: https://github.com/jernejk/EfCoreSamples.Logging