Question 247485 in Redis Question posted in
The official documentation can be found here.

Redis – How do we tie an expensive SQL Server query back to the part of C# / EF Core code that generated it?

I’m looking for a reliable strategy that will allow me to relate a performance problem that the Azure portal has highlighted, back to some query in the C# .NET 7 / EF Core 7 app that has generated that query.

In Azure I see that some query is routinely in the top expensive/slow queries

SELECT * FROM SomeMassiveTable

So, there’s no WHERE clause – I could start hunting through the codebase for all locations where db.SomeMassiveTable is used and chase them out to see if anywhere is enumerating it without applying a .Where but I’m curious to know if anyone out there has developed a better approach.

Is there a way of including an intent kind of comment with a query in a way that would show up in a trace?

For example, perhaps when the developer does something like

db.WithIntent("Cache the whole SomeMassiveTable locally into redis").SomeMassiveTable.ToList()

the Azure portal would complain the top query is:

--Cache the whole SomeMassiveTable locally into redis
SELECT * FROM SomeMassiveTable

so we could search that comment and find it in the codebase.

How about a way of grabbing a generated query (interceptors) and logging the stack trace if the query has no WHERE keyword present? Or getting some feedback from the (local dev) SQL instance itself that it’s just run an expensive query, "and here was the stack trace of the C# side that led to it…"?

I can think of various strategies to try, but I’m trying to find out if this is a problem someone has found a good solution for already

In summary, is there a good, easy to implement, built in approach for tracing problematic queries back to the originating code?

Tags:

3

Answers


  1. 0

    What you ask is possible using Query Tags but that will reveal people are using AsEnumerable(), ToList() or ToArray() to cover up unparseable LINQ queries instead of fixing them. You can save time by looking for ToList() or ToArray() in the code.

    This was a deliberate action because EF Core throws runtime errors when an unparseable LINQ query is used.

    To tag queries in the future, you need to add .TagWith(someMessage), eg:

    var myLocation = new Point(1, 2);
var nearestPeople = (from f in context.People.TagWith("This is my spatial query!")
                     orderby f.Location.Distance(myLocation) descending
                     select f).Take(5).ToList();

    That’s not as strong a warning or indicator as EF Core’s exceptions. It will catch queries that tried to bypass it though.

    The tags will be included as comments in the query itself. The query can be logged by using SQL Server Extended Events, a lightweight monitoring system that tracks all events, including query statements. SSMS shows such events using the XEvents Profiler extension.

    The comments will probably appear in Query Store reports on expensive queries

    Login or Signup to reply.
  2. 0

    To tie all EF Core SQL executions back to the calling methods, you can use an interceptor. The benefit of this solution is that you don’t need to explicitly add anything on every IQueryable in your project, this will implicitly work for all of them:

    public class AppendCallingStackTraceDbCommandInterceptor : DbCommandInterceptor
{
    public override int NonQueryExecuted(
        DbCommand command, CommandExecutedEventData eventData, int result)
    {
        AppendCallingStackTrace(command);

        return result;
    }

    public override ValueTask<InterceptionResult<int>> NonQueryExecutingAsync(
        DbCommand command, CommandEventData eventData, InterceptionResult<int> result, CancellationToken cancellationToken = default)
    {
        AppendCallingStackTrace(command);

        return ValueTask.FromResult(result);
    }

    public override InterceptionResult<DbDataReader> ReaderExecuting(
        DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result)
    {
        AppendCallingStackTrace(command);

        return result;
    }

    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(
        DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result, CancellationToken cancellationToken = default)
    {
        AppendCallingStackTrace(command);

        return ValueTask.FromResult(result);
    }

    public override InterceptionResult<object> ScalarExecuting(
        DbCommand command, CommandEventData eventData, InterceptionResult<object> result)
    {
        AppendCallingStackTrace(command);

        return result;
    }

    public override ValueTask<InterceptionResult<object>> ScalarExecutingAsync(
        DbCommand command, CommandEventData eventData, InterceptionResult<object> result, CancellationToken cancellationToken = default)
    {
        AppendCallingStackTrace(command);

        return ValueTask.FromResult(result);
    }

    [System.Diagnostics.CodeAnalysis.SuppressMessage("Security", "CA2100:Review SQL queries for security vulnerabilities", Justification = "Appends a comment, thus cannot cause a vulnerability")]
    private static void AppendCallingStackTrace(DbCommand command)
    {
        var stack = new StackTrace(true);

        // append a comment to the SQL to be executed, containing stack trace details
        command.CommandText +=
            $"{Environment.NewLine}{Environment.NewLine}/*********************{Environment.NewLine} *"
            + string.Join(
                $"{Environment.NewLine} * ",
                stack.GetFrames()
                    .Select(frame => new { frame, method = frame.GetMethod() })
                    .Select(@t =>
                        $"{@t.method?.DeclaringType?.Name}.{@t.method?.Name}: {t.frame.GetFileLineNumber()}"))
            + $"{Environment.NewLine}*********************/";
    }
}

    Registered when you add your DbContext:

    services.AddDbContext<RepaymentsDbContext>(optionsBuilder =>
{
    optionsBuilder.AddInterceptors(new[]
    {
        new AppendCallingStackTraceDbCommandInterceptor(),
    });
});

    Customise the AppendCallingStackTrace method to taste!

    Login or Signup to reply.
  3. 0

    Another option worthy to try is EntityFrameworkQueryableExtensions.TagWithCallSite Method that creates a tag with source file name and line where method was called. Examples can be found here.

    public static IQueryable<T> TagWithSource<T>(this IQueryable<T> queryable,
    string tag = default,
    [CallerLineNumber] int lineNumber = 0,
    [CallerFilePath] string filePath = "",
    [CallerMemberName] string memberName = "",
    [CallerArgumentExpression("queryable")]
    string argument = "")
{
    // argument could be multiple lines with whitespace so let's normalize it down to one line
    var trimmedLines = string.Join(
        string.Empty,
        argument.Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries).Select(i => i.Trim())
    );

    var tagContent = string.IsNullOrWhiteSpace(tag)
        ? default
        : tag + Environment.NewLine;

    tagContent += trimmedLines + Environment.NewLine + $" at {memberName}  - {filePath}:{lineNumber}";

    return queryable.TagWith(tagContent);
}
    Login or Signup to reply.
Please signup or login to give your own answer.

Back To Top
Search