In EF Core 5, there are many ways to expose what's going on along its workflow and interact with that information. These access points come in the form of logging, intercepting, event handlers, and some super cool new debugging features. The EF team even revived an old favorite from the very first version of Entity Framework. My recent CODE Magazine overview, EF Core 5: Building on the Foundation introduced you to a few of these capabilities. In this article, I'll dive more deeply into a broader collection of intriguing ways to access some of EF Core 5's metadata.
ToTraceString Revived as ToQueryString
This one is a blast from the past. In the first iterations of Entity Framework, there was no built-in logging. But there was at least ObjectQuery.ToTraceString(), a runtime method that would work out the SQL for a LINQ or Entity SQL query on the fly. Although it wasn't a great way to log as it still required you to provide your own logic to output that SQL, there are some helpful use cases for it even today. This feature hasn't been part of EF Core until this latest version, EF Core 5, and has been renamed ToQueryString().
If you want to see what SQL is generated for the simple query of a DbSet called People, you just append ToQueryString to the query. There's no LINQ execution method involved. In other words, you're separating the query itself from the execution method, which would trigger the query to run against the database.
var sqlFromQuery=context.People.ToQueryString();
One interesting use case for ToQueryString is to look at its result while debugging so that you don't have to wait until after you've run your method to inspect SQL in logs.
In the case above, I could build the query, capture the string, and then execute the query.
private static void GetAllPeople()
{
using var context = new PeopleContext();
var query = context.People.Where(p=>p.FirstName=="Julie");
var sqlFromQuery = query.ToQueryString();
var people = query.ToList();
}
Then when debugging, I could see the expected SQL for the sqlFromQuery variable. But you don't need to embed this in your production code. In fact, I wouldn't recommend that because it can easily impact performance as EF Core goes through its process of working out the SQL. Instead, you can call ToQueryString in the debugger, as shown in Figure 1.
The query variable in Figure 1 has already been evaluated as a DbQuery before I called ToQueryString in the debugger, and so that works. However, although you can debug the context and express a DbSet directly in the debugger, which means you could also run context.People.ToQueryString() in the debugger successfully, you can't evaluate LINQ expressions directly. In other words, if you were to debug the context variable and then tack on the Where method in the debugger, it will fail. That's nothing new and not a limitation of ToQueryString.
One last important point about ToQueryString in this scenario is that its evaluation is based on the simplest execution: ToList. Using a LINQ execution query such as FirstOrDefault affects how the SQL is rendered and therefore ToQueryString renders different SQL than the SQL sent to the database when executing the query with FirstOrDefault. Gunnar Peipman has some good examples of this in his blog post: https://gunnarpeipman.com/ef-core-toquerystring.
Another use case where I find ToQueryString particularly helpful is in integration tests. If you need to write tests whose success depends on some part of the generated SQL expression, ToQueryString is a much simpler path than logging. With logging, you would have to capture the log into a text writer and then read that text. Although it may be tempting to use the InMemory provider for tests like these, keep in mind that the InMemory provider does not generate SQL. You'll need to use a provider for a true database. However, the database does not need to exist in order to use ToQueryString. EF Core only works in memory to determine the SQL.
Another use case where I find ToQueryString particularly helpful is in integration tests.
Here's an example of a silly test to prove that EF Core writes more intelligent SQL than I do. Note that I'm referencing the Microsoft.EntityFrameworkCore.Sqlite provider in my test project. As you may know, EF and EF Core always project the columns related to the properties of the entity. It does not write SELECT *.
[TestMethod]
public void SQLDoesNotContainSelectStar()
{
var builder = new DbContextOptionsBuilder();
builder.UseSqlite("Data Source=testdb.db");
using var context = new PeopleContext(builder.Options);
var sql=context.People.ToQueryString();
Assert.IsFalse(sql.ToUpper().Contains("SELECT *"));
}
A more interesting example would be if you're using an interceptor to perform soft deletes and a global query filter to always filter out those rows. Here, for example, is a query filter in my DbContext OnModelBuildling method telling EF Core to append a predicate to filter out Person rows whose IsDeleted property is true.
modelBuilder.Entity<Person>().HasQueryFilter(p => !p.IsDeleted);
With this in place, I can write a test similar to the one above, but changing the assertion to the following to make sure I don't break the global query filter logic.
Assert.IsTrue(sql.ToUpper().Contains("WHERE NOT (\"p\".\"IsDeleted\")"));
You can see the full soft delete implementation in the download associated with the article online.
Logging Details from the EF Core Pipeline
There are three ways to tap into EF Core's pipeline. One is with the simple logging that I introduced in my earlier article.
Simple logging works in conjunction with .NET's logging API but all the hard work is done under the covers for you. You can easily configure the DbContext using a LogTo method, directing the .NET logging API to output logs about a DbContext instance. And there are quite a lot of events that EF Core will output. These are grouped into the following classes that derive from DbCloggerCategory.
- ChangeTracking
- Database.Command
- Database.Connection
- Database.Transaction
- Database
- Infrastructure
- Migrations
- Model.Validation
- Model
- Query
- Scaffolding
- Update
You can use these categories to filter output to only the type of information you want to log.
One parameter of LogTo specifies the target - either a console window, a file, or the debug window. Then a second parameter allows you to filter by .NET LogLevel plus any DLoggerCategoy you're interested in. This example configures a DbContext to output logs to the console using a delegate for Console.WriteLine and it filters on all the DbLoggerCategory types that fall into the LogLevel.Information group.
optionsBuilder.UseSqlServer(myConnectionString)
.LogTo(Console.WriteLine,LogLevel.Information);
This next LogTo method adds a third parameter - an array of DbLoggerCatetory (only one is included) to further filter on only EF Core's Database commands. Along with the LogTo method, I've added the EnableSensitiveDataLogging method to show incoming parameters in the SQL. This will capture all SQL sent to the database: queries, updates, raw SQL and even changes sent via migrations.
.LogTo(Console.WriteLine, LogLevel.Information,
new[]{DbLoggerCategory.Database.Command.Name},
)
.EnableSensitiveDataLogging();
My Person type that includes the IsDeleted property from above also has a FirstName and LastName property. Here's the log when calling SaveChanges after adding a new Person object.
info: 1/4/2021 17:56:09.935
RelationalEventId.CommandExecuted[20101]
(Microsoft.EntityFrameworkCore.Database.Command)
Executed DbCommand (22ms) [Parameters=[
@p0='Julie' (Size = 4000), @p1='False',
@p2='Lerman' (Size = 4000)],CommandType='Text',
CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [People] ([FirstName],[IsDeleted], [LastName])
VALUES (@p0, @p1, @p2);
SELECT [Id]
FROM [People]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();
The logger displays the LogLevel type (info), the DbContext EventId (RelationalEventId.CommandExecuted), and the details of the logger category I requested. Next it states the log name, the execution time, and the parameter list. Because sensitive data logging is enabled, the parameters are displayed. Finally, it lists the SQL sent to the database.
LogTo makes it easy to have EF Core output basic logging. You can configure it in the DbContext, in the Startup file of an ASP.NET Core app, or in an ASP.NET Core app's application configuration file.
Notice the EventId at the top. You can even define your logging to filter on specific events using those IDs. You can also filter out particular log categories and you can control the formatting. Check out the docs for more details on these various capabilities at https://docs.microsoft.com/en-us/ef/core/logging-events-diagnostics/simple-logging.
Simple logging is a high level way to log EF Core, but you can also dive more deeply into the logger by working directly with Microsoft.Extensions.Logging to exert even more control over how EF Core's logs are emitted. Check the EF Core docs for more details on getting started with this more advanced usage: https://docs.microsoft.com/en-us/ef/core/logging-events-diagnostics/extensions-logging.
Responding to EF Core Events
EF Core 2.1 introduced .NET events in the EF Core pipeline. There were only two to begin with: ChangeTracker.Tracked, which is raised when the DbContext begins tracking an entity, and ChangeTracker.StateChanged is raised when the state of an already tracked entity changes.
With the base logic in place, the team was able to add three more events to EF Core 5 for SaveChanges and SaveChangesAsync.
- DbContext.SavingChanges is raised when the context is about to save changes.
- DbContext.SavedChanges is raised after either of the two save changes methods have completed successfully.
- DbContext.SaveChangesFailed is used to capture and inspect a failure.
It's nice to be able to separate this logic rather than stuffing it all into a single override of the SaveChanges method.
You could even use these events to emit alternate information that's not tracked by the logger. The EF Core docs use an example where they output timestamps when data is added, updated, or deleted.
You could even use
theseevents to emit alternate information that isn't tracked by the logger.
If you're using shadow properties to track audit data, you could use the SavingChanges event to update those properties before the SQL is constructed and sent to the database.
For example, I set up my application to add a UserId shadow property to every entity (barring those that are property bags and owned entities). My application has a static variable called Globals.CurrentUserId set by my application when a user logs in. Also, in my DbContext class, I've created a private method called SetUserId that sets the value of my shadow property (where it exists) to that CurrentUserId.
private void SetUserId(object sender, SavingChangesEventArgs e)
{
foreach (var entry in ChangeTracker.Entries()
.Where(entry => entry.Metadata
.GetProperty("UserId") != null))
{
entry.Property("UserId").CurrentValue = Globals.CurrentUserId;
}
}
Finally, I can wire up the SetUserId method to the SavingChanges event in the constructor of the DbContext:
public PeopleContext()
{
SavingChanges += SetUserId;
}
Now any time I call SaveChanges, the UserId gets persisted into the table along with the other data. Here's some log data that shows 101, the value of my CurrentUserId, as part of the data inserted into a new Person row:
Executed DbCommand (29ms) [Parameters=[
@p0='Julie' (Size = 4000), @p1='False',
@p2='Lerman' (Size = 4000), @p3='101'],
CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [People] ([FirstName],[IsDeleted], [LastName], [UserId])
VALUES (@p0, @p1, @p2, @p3);
SELECT [Id]
FROM [People]
WHERE @@ROWCOUNT = 1
AND [Id] = scope_identity();
You can see the full implementation in the download with this article. It's just one simple way to leverage these events.
Accessing Metrics with Event Counters
EF Core 5 takes advantage of a cool feature introduced to .NET in .NET Core 3.0 - dotnet-counters (https://docs.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-counters). Dotnet-counters is a global command line tool. You can install this tool using the dotnet CLI.
dotnet tool install --global dotnet-counters
Once installed, you can then tell it to monitor different processes running in the dotnet environment. You'll need to provide the process ID of your running .NET application with
System.Diagnostics.Process.GetCurrentProcess().Id
In Visual Studio, I wasn't able to simply ask for this value in the debugger. The debugger will only tell you that “This expression causes side effects and will not be evaluated.” So I embedded it into my code and received the value 28436.
With the ID in hand and the app still running, you can then trigger the counter to begin monitoring events coming from the Microsoft.EntityFramework namespace. Note that I've wrapped the command for display purposes.
dotnet counters monitor Microsoft.EntityFrameworkCore -p 28436
Then, as you run through your application, the counter displays a specific list of EF Core stats, as shown in Figure 2, and then update the counts as the application performs its functionality. I only used it with a small demo app so my counts aren't very interesting, but you can see that I have a single DbContext instance running (Active DbContexts), I've run three queries, leveraged the query cache (because I ran some of those queries more than once), and called SaveChanges twice.
This looks like another interesting tool to have in your analysis toolbelt, but will certainly be more useful when running against a more intensive solution. In the docs, the EF team recommends that you do read up on the dotnet-counters feature to properly benefit from using it with EF Core.
Intercepting EF Core's Pipeline to the Database
Another area of EF Core's pipeline is related to its interaction with the database. On the way to the database, there are tasks such as preparation of SQL commands and connections. On the way back from the database, there are tasks such as reading the database results and materializing objects. EF Core's interceptors are a feature that began in EF6 and was re-introduced in EF Core 3. A new interceptor for SaveChanges was introduced in EF Core 5.
EF Core's interceptors are a feature that began in EF6 and was re-introduced in EF Core 3.
Because this feature has been around for a long time (although it's fairly new to EF Core), much has already been written and shared about it. Even so, I always find it interesting to be reminded of all of the objects you can intercept and modify before they continue on the pipeline. Note that some of the parameters coming from the new version are simpler to work with.
There are three different interceptor classes to intercept commands, connections, and transactions as well as the new interceptor class for SaveChanges. Each class exposes virtual methods (and relevant objects) related to its category. For example the DbCommandInterceptor exposes ReaderExecuting and ReaderExecutingAsync, which is triggered as the command is about to be sent to the database.
public override InterceptionResult<DbDataReader>
ReaderExecuting(
DbCommand command,
CommandEventData eventData,
InterceptionResult<DbDataReader> result)
{
//e.g., alter command.CommandText
return result;
}
One of its parameters is a DbCommand, and its CommandText property holds the SQL. If you want to modify the SQL, add query hints, or other tasks, you can change the command.CommandText and then command with the new CommandText value will continue on its way.
The ReaderExecuted/Async methods are triggered as any resulting data is returned from the database.
public override DbDataReader ReaderExecuted(
DbCommand command,
CommandExecutedEventData eventData,
DbDataReader result)
{
return base.ReaderExecuted
(command, eventData, result);
}
Here, for example, you could capture the DbDataReader stored in the result variable and do something with that data before it continues on to EF Core for object materialization. One example is logging something that the logger doesn't capture, such as the newly generated ID value of a row added to the database. The result variable from a query shown in Figure 3 while debugging shows that there are rows returned and each row has five fields.
You'll find an example of an interceptor in the download but might also appreciate some more detailed blog posts from community members. One is by Lizzy Gallagher, which is a nice introduction to interceptors in EF Core (https://lizzy-gallagher.github.io/query-interception-entity-framework/), and another is a more in-depth article by Eddie Stanley https://eddiewould.com/2019/02/22/entityframework-fun-with-dbcommandinterceptor/. Keep in mind that Eddie's article is based on EF6 and some of the method parameters are different, but he demonstrates some cool ideas.
There's a lot of guidance around working with the interceptors in the EF Core docs at https://docs.microsoft.com/en-us/ef/core/logging-events-diagnostics/interceptors.
A Sleeper Feature in EF Core 5: Debug Views
You may or may not be familiar with the term “sleeper” used to describe, for example, a great movie that not many people are aware of. There are two new features added to EF Core 5 that I didn't even know existed until Arthur Vickers showed them in the EF Community Standup just after EF Core 5 was released. (Entity Framework Community Standup - Special EF Core 5.0 Community Panel, https://www.youtube.com/watch?v=AkqRn2vr1lc, at about 41 minutes.) These are the ChangeTracker.DebugView and Model.DebugView.
The DebugViews output nicely formatted strings filled with information about the state of a context's ChangeTracker or metadata from the model. DebugView provides a beautiful document that you can capture and print out and really get a good look at what's going on under the covers. I spend a lot of time in the debugger drilling into explore various details about what the change tracker knows or how EF Core is interpreting the model I've described. The ability to read this information in this text format, even save it in a file so you don't have to debug repeatedly to glean details, is a fantastic feature of EF Core 5. In fact, making sure you know about DebugViews was my inspiration for writing this article.
Making sure you know about DebugViews was my inspiration for writing this article.
The way to get to this information is when debugging an active DbContext instance. In DbContext.ChangeTracker.DebugView, you'll find a ShortView and a LongView property. Here, for example, is the ShortView of my context when I've just queried for a single person object and my context only contains that one Person.
Person {Id: 1} Unchanged
That's the most commonly needed information - relaying that there's only one unchanged Person whose ID is 1 in my context.
The LongView provides some more detail about the entity that's being tracked.
Person {Id: 1} Unchanged
Id: 1 PK
FirstName: 'Julie'
IsDeleted: 'False'
LastName: 'Lerman'
UserId: 101
Addresses: []
If I were to edit that Person while it's still being tracked and force the context to detect changes, the LongView, in addition to showing the state as Modified, also notes the change I made to the LastName property.
Person {Id: 1} Modified
Id: 1 PK
FirstName: 'Julie'
IsDeleted: 'False'
LastName: 'Lermantov' Modified
Originally 'Lerman'
UserId: 101
Addresses: []
You can see in this view that there's an Addresses property. In fact, Person and Address have a many-to-many relationship between them using skip navigations. EF Core infers the PersonAddress entity in memory at run time in order to persist the relationship data into a join table. When I create a graph of a person with one address in its Addresses collection, you can see a Person, an Address, and an inferred PersonAddress object in the ShortView. The long view shows the properties of these objects.
AddressPerson (Dictionary<string, object>)
{AddressesId: 1, ResidentsId: 1} Unchanged FK
{AddressesId: 1} FK {ResidentsId: 1}
Address {Id: 1} Unchanged
Person {Id: 1} Modified
I love these debug views that help me at debug time to discover the state and relationship of my tracked objects whether I'm problem solving or just learning how things work.
Let's flip over to the Model.DebugViews to see what you can learn from them. First, I should clarify my model. It's the same model I used for the earlier article. In Figure 4, I'm using the EF Core Power Tools extension in Visual Studio to visualize how EF Core interprets my model. My classes are Person, Address, Wildlife Sighting, and ScaryWildlifeSighting. As mentioned already, Person and Address have a many-to-many relationship where EF Core infers a join entity. WildlifeSighting has a one-to-many relationship with Address, and ScaryWildlifeSighting inherits from WildlifeSighting using a Table-Per-Hierarchy mapping to the database.
The DbContext.Model.DebugView also has a ShortView and a LongView. And they both contain a lot of information. Listing 1 shows the ShortView. There's so much information in here. You can see properties, primary and foreign keys, indexes, and cascade delete rules. The many-to-many relationship is described, even specifying that it's using a skip navigation. The inheritance is also described. There's so much you can learn from this document. I like that you can capture it and save it in your documentation for team members to refer to as needed. You could also use it to compare the model as you evolve your app to make sure you haven't broken any of EF Core's interpretation of your model.
Listing 1: The Model.DebugView.ShortView of my data model
Model:
EntityType: AddressPerson (Dictionary<string, object>)
CLR Type: Dictionary<string, object>
Properties:
AddressesId (no field, int) Indexer Required PK FK AfterSave:Throw
ResidentsId (no field, int) Indexer Required PK FK Index AfterSave:Throw
Keys:
AddressesId, ResidentsId PK
Foreign keys:
AddressPerson (Dictionary<string, object>) {'AddressesId'} -> Address {'Id'} Cascade
AddressPerson (Dictionary<string, object>) {'ResidentsId'} -> Person {'Id'} Cascade
Indexes:
ResidentsId
EntityType: Address
Properties:
Id (int) Required PK AfterSave:Throw ValueGenerated.OnAdd
PostalCode (string)
Street (string)
UserId (no field, int) Shadow Required
Navigations:
WildlifeSightings (List<WildlifeSighting>) Collection ToDependent WildlifeSighting
Skip navigations:
Residents (List<Person>) CollectionPerson
Inverse: Addresses
Keys:
Id PK
EntityType: Person
Properties:
Id (int) Required PK AfterSave:Throw ValueGenerated.OnAdd
FirstName (string)
IsDeleted (bool) Required
LastName (string)
UserId (no field, int) Shadow Required
Skip navigations:
Addresses (List<Address>) CollectionAddress
Inverse: Residents
Keys:
Id PK
EntityType: WildlifeSighting
Properties:
Id (int) Required PK AfterSave:Throw ValueGenerated.OnAdd
AddressId (int) Required FK Index
DateTime (DateTime) Required
Description (string)
UserId (no field, int) Shadow Required
Keys:
Id PK
Foreign keys:
WildlifeSighting {'AddressId'} -> Address {'Id'}
ToDependent: WildlifeSightings Cascade
Indexes:
AddressId
The Model.DebugView.LongView has even more detail, describing annotations, database mappings, and more. Listing 2 shows only the output for the Person entity. There's even more you can learn from the LongView. This level of detail isn't something everyone will want to look at but it's there if you need it. Looking at this type of information is how I learned so much about Entity Framework and EF Core in the early days and I continue to be fascinated by it. Note that it's a lot easier to read in the text viewer than in the listing because I had to wrap so many lines in order to fit into the listing format for the printed page. Figure 5 shows a screenshot of part of the LongView so you can better see how it's formatted.
Listing 2: The Person entity described in the LongView of Model.DebugView
EntityType: Person
Properties:
Id (int) Required PK AfterSave:Throw ValueGenerated.OnAdd
Annotations:
Relational:DefaultColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMappingBase]
Relational:TableColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMapping]
SqlServer:ValueGenerationStrategy: IdentityColumn
FirstName (string)
Annotations:
Relational:DefaultColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMappingBase]
Relational:TableColumnMappings:System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMapping]
IsDeleted (bool) Required
Annotations:
Relational:DefaultColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMappingBase]
Relational:TableColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMapping]
LastName (string)
Annotations:
Relational:DefaultColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMappingBase]
Relational:TableColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMapping]
UserId (no field, int) Shadow Required
Annotations:
Relational:DefaultColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMappingBase]
Relational:TableColumnMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.ColumnMapping]
Skip navigations:
Addresses (List<Address>) CollectionAddress
Inverse: Residents
Keys:
Id PK
Annotations:
Relational:UniqueConstraintMappings: System.Collections.Generic.SortedSet`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.UniqueConstraint]
Annotations:
ConstructorBinding: Microsoft.EntityFrameworkCore.Metadata.ConstructorBinding
QueryFilter: p => Not(p.IsDeleted)
Relational:DefaultMappings: System.Collections.Generic.List`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.TableMappingBase]
Relational:TableMappings: System.Collections.Generic.List`1
[Microsoft.EntityFrameworkCore.Metadata.Internal.TableMapping]
Relational:TableName: People
ServiceOnlyConstructorBinding:
Microsoft.EntityFrameworkCore.Metadata.ConstructorBinding
Take Advantage of the Pipeline
I'm a big fan of understanding how the tools I use work. Luckily, I leave the power tools to my husband (a carpenter) and stick to my own tools, such as EF Core. The more you know about what's going on under the covers, the more power you have over that tool. For example, comprehending how EF Core interprets your classes and mappings gives you more agency over designing interesting models that persist data exactly the way you want it to. Knowing that you can modify the SQL or even the results based on your needs lets you build more intelligent applications. Learning how to leverage the various debugging, logging, interception, and event handling explained in this article can turn you into the EF Core expert on your team.
