Combine Extended Events and TagWith to Monitor Entity Framework

I'm going to start with a sentence that makes a lot of people crazy; as a DBA and database developer, I love Entity Framework.

That's right. Entity Framework is the bomb. It's amazing. It does wonderful stuff. Entity Framework makes the developers lives and jobs easier. It makes my life and job easier.

Yes, Entity Framework will improve your job quality and reduce stress in your life.

With one caveat, it gets used correctly.

That's the hard part, right? There is tons of technology that makes things better if used correctly. There are all sorts of programs that make your life easier if used correctly. Yet all of these, if used incorrectly, can make your life a living hell.

One problem that I've always had with Entity Framework is that it's very difficult to tell what part of the code the call was coming from. You really have no idea. So when my friend, Chris Woodruff, asked me on Twitter what would be the best way to monitor TagWith queries in Entity Framework, well, first, I had to go look up what TagWith was, then I got real excited because, hey, here's a solution.

What the Heck Is TagWith in Entity Framework?

I know. Same question I asked. To make it a little easier, try searching the Microsoft documentation for the phrase "Query Tags." You'll then find some excellent documentation. You'll also find that this was only introduced relatively recently in Entity Framework Core 2.2 (4 December 2018 release date).

The basics are really easy. Use the TagWith to mark your queries and the string you add will show up at the top of the query as a comment. Thus, the query gets marked. Therefore, you with me, you can track down exactly where in the code that query was generated. It'll be searchable within Visual Studio.

WHOOP!

Now, I'm not going to insult your intelligence by showing you the sample code in Visual Studio that I cooked up (actually, I just don't want to listen to all the insulting remarks about how bad my C# coding is, I haven't done it professionally for almost two decades, cut me some slack). If you want to know how to use TagWith appropriately, Chris Woodruff is writing a blog that acts as a companion to mine. You can read all about how best to use TagWith in Entity Framework there. However, I will show you how I was able to monitor for the query using Extended Events.

Monitoring for TagWith in Extended Events

Let's just say I have some C# code running a web page (this sure helped). Said web page has a search function in which I can look up Movie titles. If I wanted to monitor the calls from Entity Framework to this database, I could easily do this with the following Extended Events Session:

CREATE EVENT SESSION [MoviesPerformance] ON SERVER 
ADD EVENT sqlserver.rpc_completed(
WHERE ([sqlserver].[database_name]=N'Movies')),
ADD EVENT sqlserver.rpc_starting(
WHERE ([sqlserver].[database_name]=N'Movies')),
ADD EVENT sqlserver.sp_statement_completed(
WHERE ([sqlserver].[database_name]=N'Movies'))
WITH (TRACK_CAUSALITY=ON);

This would capture the calls like this:

However, it's going to capture all the queries. What if I only want to focus on that query from the search part of the process? Well, first, I have to modify my code (again, no jokes please, my feelings are very sensitive):

var movies = from m in _context.Movie.TagWith("Special Search Query")
select m;

With that in place, if I want to only monitor for this query, I need to either modify my Extended Events session or create a new one. For our purposes, I'll create a new one:

CREATE EVENT SESSION [MoviesSearchPerformance] ON SERVER 
ADD EVENT sqlserver.rpc_completed(
WHERE ([sqlserver].[equal_i_sql_unicode_string]([sqlserver].[database_name],N'Movies') AND [sqlserver].[like_i_sql_unicode_string]([statement],N'%Special Search Query%'))),
ADD EVENT sqlserver.rpc_starting(
WHERE ([sqlserver].[equal_i_sql_unicode_string]([sqlserver].[database_name],N'Movies') AND [sqlserver].[like_i_sql_unicode_string]([statement],N'%Special Search Query%'))),
ADD EVENT sqlserver.sp_statement_completed(
WHERE ([sqlserver].[equal_i_sql_unicode_string]([sqlserver].[database_name],N'Movies') AND [sqlserver].[like_i_sql_unicode_string]([statement],N'%Special Search Query%')))
WITH (TRACK_CAUSALITY=ON);

Yeah, I've just added an additional filter criteria to search the statement field for '%Special Search Query%'. That's it. Here are the results:

Note, even though I have sp_statement_completed in my session, I'm not seeing that currently. Let's look at the generated T-SQL to understand why. Here's the full call from either rpc_starting or rpc_completed:

statementexec sp_executesql N'-- Special Search Query    SELECT [m].[ID], [m].[Genre], [m].[Price], [m].[ReleaseDate], [m].[Title]  FROM [Movie] AS [m]  WHERE (CHARINDEX(@__SearchString_0, [m].[Title]) > 0) OR (@__SearchString_0 = N'''')',N'@__SearchString_0 nvarchar(4000)',@__SearchString_0=N'that'

This is the statement field from the sp_statement_completed in my first Extended Events session:

nametimestampstatementbatch_text
sp_statement_completed2019-01-30 09:05:44.8474092SELECT [m].[ID], [m].[Genre], [m].[Price], [m].[ReleaseDate], [m].[Title]  FROM [Movie] AS [m]  WHERE (CHARINDEX(@__SearchString_0, [m].[Title]) > 0) OR (@__SearchString_0 = N'')NULL

You can see that the comment is part of the full string. By the way, the statement includes the parameter values, so that's not a concern. The comment is not a part of the statement because, simply, it's not. For this kind of call from Entity Framework, having sp_statement_completed actually doesn't add any real information to what we already are collecting, so probably aren't needed.

Conclusion

As you can see, TagWith makes it really easy to mark a query in a way that's going to be visible within SQL Server. That visibility makes it possible to easily capture that information. TagWith is a wonderful addition to Entity Framework and will absolutely help make it easier for the developer and the data pro to work together on this stuff.

Make sure you read Chris Woodruff's blog post for how to deal with this appropriately on the Entity Framework side of things. Also, thanks to Chris for pointing this out to me.

Hopefully, functionality like this can help reduce the fear and loathing that is so often incorrectly felt by data pros.