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

Question

I have a problem with some slow running queries that we see only during production, and I see poorly performing SQL in the profiler, but I don’t know how this can be used to track the code that generated the statement in the first place, or if tracing back to an EF request is even possible. Does EF have the ability to identify the beginning of an SQL statement to help track down a problem in the code?

I believe that this problem may be related to loading the load, loading the pessimism, that is, when loading the entire result set and then filtering the list in the code instead of filtering it in SQL

Answer 1

In your repository or DataContext (the usual place where the request is executed), you can do the following: debug the recording of each request.

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

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

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

You can use microsoft or log4net trace to register this material, and then easily find your query.

Answer 2

You can create another object in your database (i.e.: DebugEntity) and run the query immediately before / after the actual queries.

 ctx.DebugEntity.Where(x => x.ID == "myId1"); //myId2, myId3, myId4, whatever helps you locate the LINQ query from the profiler... 

This should appear in the SQL profiler.

Answer 3

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

Something like this should do this:

 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 the DbContext constructor, you add it as an interceptor:

 DbInterception.Add(new QueryOriginInterceptor()); 

In the profiler you will see that the request is executed as follows:

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

With this approach, there are some considerations, such as performance degradation when building a stack trace, and several execution plans can be cached if the same function is called from different places.