How can I trace a SQL query generated by EF back to the code that created it

Question

I have a problem with some slow running queries that we only see in production, and I can see the poorly performing SQL in the profiler, however, I don't know how I can use this to trace back to the code that generated the statement in the first place, or if tracing back to the EF query is even possible. Does EF have any ability to identify the origin of the SQL statement to help trace down the problem in the code?

I believe this issue might be related to the code loading loading pessimistically, i.e. its loading an entire results set and then filtering a list in the code rather than filtering it in the SQL

Answer 1

Old thread, but you could implement a DbCommandInterceptor that builds a stack trace and adds it to the SQL command as a comment. This would couple the C# function that made the call with the EF SQL in the profiler and in Azure.

Something like this should do it:

public class QueryOriginInterceptor : IDbCommandInterceptor
{
    private const string _sqlCommentToken = "--";
    private const string stackLoggerStartTag = _sqlCommentToken + " Stack:";

    private bool _shouldLog = false;

    public static string StackLoggerStartTag => stackLoggerStartTag;

    public QueryOriginInterceptor(bool shouldLog = true)
    {
        _shouldLog = shouldLog;
    }

    void AppendStackTraceToSqlCommand(DbCommand command)
    {
        if (!_shouldLog)
            return;

        int positionOfExistingCommentStartTag = command.CommandText.IndexOf(stackLoggerStartTag);

        if (positionOfExistingCommentStartTag < 0)
        {
            IEnumerable<string> frames = (new StackTrace())
                .GetFrames()
                .ToList()
                .Select(f => $"{f?.GetMethod()?.ReflectedType?.FullName ?? "[unknown]"}.{f?.GetMethod()?.Name}")
                .Where(l => !l.StartsWith("System.") && !l.StartsWith(this.GetType().FullName));

            string comment = $"{stackLoggerStartTag}{Environment.NewLine}{_sqlCommentToken} {string.Join($"{Environment.NewLine}{_sqlCommentToken} ", frames)}{Environment.NewLine}";
            command.CommandText = $"{Environment.NewLine}{comment}{command.CommandText}";
        }
    }

    void IDbCommandInterceptor.ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) => AppendStackTraceToSqlCommand(command);

    void IDbCommandInterceptor.NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) => AppendStackTraceToSqlCommand(command);

    void IDbCommandInterceptor.ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) => AppendStackTraceToSqlCommand(command);

    void IDbCommandInterceptor.NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) { }

    void IDbCommandInterceptor.ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) { }

    void IDbCommandInterceptor.ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) { }
}

Then in your DbContext constructor, you add it as an interceptor:

DbInterception.Add(new QueryOriginInterceptor());

In the profiler, you'd see the query being executed like so:

-- Stack:
-- YourApp.Users.GetUser
SELECT
    [Project1].[ID] AS [ID],
    FROM [dbo].[User]
WHERE [Extend1].[ID] = @p__linq__0

There are some considerations with this approach, such as the performance hit of building the stack trace, and there might be multiple execution plans cached if the same function is called from different locations.

Answer 2

You can do the following, in your Repository or DataContext (common place where query is executing) to debug write every query.

 var data= from item in entity
                 where item.id = 564564
                 select item;    
 Debug.WriteLine(((System.Data.Objects.ObjectQuery)data).ToTraceString());

You can write following code to say what is the call stack when above query was executed. Then find the query you looking for and call stack will tell you where the query was executed.

StackTrace stackTrace = new StackTrace();           // get call stack
StackFrame[] stackFrames = stackTrace.GetFrames();

You can use microsoft tracing or log4net to log this stuff and then easily find your query.