October 2018
Volume 33 Number 10
[Data Points]
Logging SQL and Change-Tracking Events in EF Core
By Julie Lerman
.jpg "Julie Lerman")
The addition of the flexible logging APIs in .NET Core has been a boon to development. EF Core ties into those APIs, allowing you to expose a variety of logging and debugging information coming from EF Core.
In this month’s column, I want to show you some of the types of information you can get from EF Core at run time, a few of the ways to surface that information and, as usual, pass along various tips and tricks I’ve learned along the way.
Although the logging capability is available for anything that sits on top of the .NET Core SDK, you’ll find that most of the documentation is for how ASP.NET Core uses it. See, for example, the official Microsoft doc on ASP.NET Core Logging at bit.ly/2OiS4HD.
You can target the output to a variety of destinations, thanks to the ILoggerFactory, which can use built-in providers such as the ConsoleLoggerProvider and the DebugLoggerProvider, and can even integrate with Windows events, AzureAppServices and more. The providers are encapsulated in various extensions, such as Microsoft.Extensions.Logging.Console. Because my goal here is to show you the type of information EF Core can expose, not how to integrate with the various providers, I do recommend looking at the aforementioned ASP.NET Core Logging article, as well as Mark Michaelis’s article, “Logging with .NET Core,” at msdn.com/magazine/mt694089.
Here, I’ll only use the providers that output to the console and the debugger.
The logging extensions are dependent on. NET Standard. That means you can use the logging in .NET Framework 4.6.1 and higher apps or in .NET Core and ASP.NET Core. ASP.NET Core has the logging built in and it’s a lot easier to tap into it there. But I’ll use a .NET Framework app and configure the logging directly in a DbContext class in order to demonstrate surfacing EF Core logging, as there are already so many examples of using logging from ASP.NET Core.
EF Core Logging in General
In order to surface EF Core logging information, you need to tie an ILoggerFactory to a DbContext. The DbContext will then share information with that logger factory. ASP.NET Core does this for you, but outside of ASP.NET Core this step must be done explicitly.
First you need to define a LoggerFactory object, and this is where you can specify which providers that LoggerFactory should use. Given that I already have a reference to Microsoft.Extensions.Logging.Console and a using statement to that namespace in my DbContext class, this is the simplest way to define a LoggerFactory that will output to a console window.
The different providers have their own constructor definitions. For example, the ConsoleProvider has four different constructors that take different objects to express settings for the provider. One of those constructors takes a lambda expression to surface a logging level and a logging category. Logging levels help organize different classes of logging details. One level consists of logs containing some basic information. Another holds more detailed logs to help in debugging a problem. The APIs that are sharing their information with the logger determine in which level their data belongs. For example, the database commands surfaced by EF Core are tagged as both Information and Debug log level. The change tracker details surfaced by EF Core are tagged as the Debug level. I’ll show you some examples of these.
The categories are determined by the type of information being shared. EF Core 2.1 exposes 12 different categories of logging information. The EF Core LoggerCategory class at bit.ly/2KBLWs1 is a handy reference, where you’ll find a list of categories that derive from it, as shown in Figure 1.
Figure 1 EF Core LoggerCategory Classes
| ChangeTracking | Migrations |
| Database | Model |
| Database.Command | Model.Validation |
| Database.Connection | Scaffolding |
| Database.Transaction | Query |
| Infrastructure | Update |
Notice there are even log events exposed for migrations commands.
The log levels and categories make it easy to filter what’s output by the logger—I’ll use that to show you just the SQL and ChangeTracker details.
Examining EF Core’s Generated SQL
Logging the SQL commands generated by EF Core activity may be the most common logging task you’ll want to perform with EF Core. Of course, you always have the option of using SQL profiling tools such as the SQL Profiler for Windows, EF Prof (efprof.com) and the (in preview) profiling feature of the cross-platform SQL Operations Studio (bit.ly/2MnfN94). But you may not always have access to these tools, especially if you want to trigger logs from a user’s app, not on a developer machine.
So, let’s start by creating a logger factory that spits out the SQL sent to the database. The SQL commands are exposed through the Database.Command category.
I’ll create a LoggerFactory named DbCommandConsoleLoggerFactory and then explain the code:
public static readonly LoggerFactory DbCommandConsoleLoggerFactory
= new LoggerFactory (new [] {
new ConsoleLoggerProvider ((category, level) =>
category == DbLoggerCategory.Database.Command.Name &&
level == LogLevel.Information, true)
});
Notice that the LoggerFactory is static. The EF team (and the docs) advise that you use the same logger for every instance of a context during the application lifetime. Otherwise, you can encounter some strange side effects, as well as slow EF Core’s processing dramatically. Making this logger factory static ensures that it will remain in scope and available for every new instance of the context throughout the app’s lifetime.
A logger factory can be composed of one or more providers, allowing you to spit out logs to multiple destinations concurrently, but I’ll only add one. This constructor takes an array of different logger providers. After defining the array via new [], I add only a single provider—a ConsoleLoggerProvider. Of the four available constructors for that provider, I’ll use the one that lets me filter using a lambda composed from the category and level of the log. The first parameter is the predicate I’ll use for filtering. I’m providing variable names—category and level—to the values of the expression and then building the filter from those to indicate that the category (a string) should be equal to the name of the Database.Command class and the level should be equal to the LogLevelInformation enum.
Database.Command outputs SQL plus a few other detailsthrough the Debug level, but only SQL commands through the Information level. So you’re better off specifying just one of the LogLevels or you’ll get redundant commands. Debug will output commands as Executing, whereas Information will output them as Executed.
The second parameter is a Boolean for the IncludeScope option. Log scopes allow you to group logs, but as far as I know, EF Core doesn’t use them.
With a LoggerFactory defined, it must then be tied to a DbContext, which you can do within the OnConfiguring method. UseLoggerFactory is a method of DbContextOptionsBuilder. If you’re defining other options, such as UseSqlite, you can append UseLoggerFactory. Otherwise, you can just call it directly from the optionsBuilder. Either way, you then pass in the factory that’s defined in your class:
optionsBuilder.UseLoggerFactory(DbCommandConsoleLoggerFactory)
By default, EF Core will protect you from exposing sensitive data, such as filter parameter values. When I’m debugging my own code, I often add the EnableSensitiveDataLogging method to expose that:
optionsBuilder.UseLoggerFactory(
DbCommandConsoleLoggerFactory).EnableSensitiveDataLogging();
With the context now set up to expose this data, I have a console application that creates some data and saves it to the database to which my context is mapped. All I’m doing is creating a single magazine and adding a new article to its articles collection:
using (var context = new PublicationsContext())
{
var mag = new Magazine("MSDN Magazine", "1105 Media");
var article = new Article("EF Core 2.1 Query Types","Julie Lerman");
mag.Articles.Add(article);
context.Magazines.Add(mag);
var results=context.SaveChanges();
Console.ForegroundColor = ConsoleColor.Red;
Console.WriteLine($"Program Message: The app has stored {results} rows");
}
The logger outputs three sets of Information followed by my Program Message output (see Figure 2). Note that I’m mixing logging and Console WriteLine messages here specifically for this simple demo. But you shouldn’t do this in a production application because there is a chance of processing conflicts and logging messages not reaching the console.
.png "Log Output When Filtering on Information Level Database.Commands")
Figure 2 Log Output When Filtering on Information Level Database.Commands
Each message from the logger is prefaced by a line that says:
"info: Microsoft.EntityFrameworkCore.Database.Command[20101].
20101 is the unique EventId assigned to Executed DbCommand events.
The first line is a special command SQLite sends by default for each newly opened connection to ensure that foreign keys are honored. The next command inserts the new magazine and returns its newly generated primary key. The last command inserts the article along with the magazine’s key value into the MagazineId foreign key column and returns its newly generated primary key. Finally, the console app outputs my own message, which I specified with Console.WriteLine.
Notice that the info items say “Executed DbCommand,” even relaying the time the command took to execute and return the results to EF Core to continue processing those results. Because I enabled sensitive data logging, you can also see the parameter values that were passed in.
If I were to change the LogLevel from Information to Debug, the output would be slightly different, as shown in Figure 3. The flags are dbug rather than info. The SQL is still logged but as “Executing DbCommand” with an event id of 20100, in contrast to the Executed DbCommand events where the event ids were 20101. Moreover, Database.Command relayed two additional events when the data readers were disposed after receiving the new PrimaryKeys in the results from the SELECT statements.
.png "Database.Commands from LogLevel.Debug")
Figure 3 Database.Commands from LogLevel.Debug
Let’s look at a DebugLoggerProvider outputting the same Database.Commands.
First, I’ll create another LoggerFactory, this time one that just pushes logs through a DebugLoggerProvider. This provider has only two constructors, but one of them is similar to the ConsoleLoggerProvider’s constructor—taking in a filter lambda expression but without the IncludeScope parameter. My new LoggerFactory looks pretty close to the other:
public static readonly LoggerFactory DbCommandDebugLoggerFactory
= new LoggerFactory (new [] {
new DebugLoggerProvider(
(category, level) => category == DbLoggerCategory.Database.Command.Name &&
level == LogLevel.Information)
);
After modifying the optionsBuilder.UseLoggerFactory to use this object, my console displays only the Program Message and Press any key output.
But if I change the Visual Studio Output window to display Debug output, I can see the SQL commands output by the logger in between the Visual Studio debug messages. Figure 4 displays some of this output. Notice that the EF Core logs don’t have the “info” flags or the Event Ids, but do list the category followed by the name of the log level.
.png "Database.Commands Written out to the Debug Window")
Figure 4 Database.Commands Written out to the Debug Window
Now let’s take a look at the ChangeTracking category. How the EF Core change tracker works is very interesting to me—dare I say fascinating? I hope you agree. All of the events in this category fall into the debug log level.
I’ll create another LoggerFactory using the ConsoleLoggerProvider again, but this time my filter combines Database.Commands and ChangeTracking events. By filtering on Debug level, I can get not only all of the ChangeTracking events, but also the SQL captured by the commands. Remember that debug raises Executing DbCommand events and a few others:
public static readonly LoggerFactory ChangeTrackingAndSqlConsoleLoggerFactory
= new LoggerFactory(new[] {
new ConsoleLoggerProvider (
(category, level) =>
(category == DbLoggerCategory.ChangeTracking.Name |
category==DbLoggerCategory.Database.Command.Name)
&& level==LogLevel.Debug ,true)
});
After switching the optionsBuilder to use this logger factory, the output is quite different! The first part of that output is shown in Figure 5. If you’re not familiar with how the change tracker goes about its business, this may be especially interesting to you. Note that the second debug log in Figure 5 switches the context name with the entity name—a known bug who’s fix will appear in EF Core 2.2.
Figure 5 First Part of ChangeTracking and Database.Command Category Events
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10808]
'PublicationsContext' generated temporary value '-2147482647' for
the 'MagazineId' property of new 'Magazine' entity.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
Context 'Magazine' started tracking '{MagazineId: -2147482647}'
entity with key 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10808]
'PublicationsContext' generated temporary value '-2147482647' for
the 'ArticleId' property of new 'Article' entity.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
Context 'Article' started tracking '{ArticleId: -2147482647}'
entity with key PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10800]
DetectChanges starting for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10801]
DetectChanges completed for 'PublicationsContext'.
As before, each of the entries is prefaced by the category with the relevant Event Id. The events begin when my method calls context.Magazines.Add.
The first event is that the context generated a temporary key value (EventId 10808) for the new magazine and then it began tracking the key (EventId 10806). Next, the context repeated the same two steps (EventIds 10808 and 10806 again) for the new article. The temporary key values are the same because they’re different entity types and -2147482647 is the starting point for temporary key values.
After adding the magazine and its article to the context, I then call SaveChanges. This triggers DetectChanges and you can see an event for when it started and when it ended. Because there are no changes to the entities from the time they were tracked, there’s nothing to discover, so this is followed immediately by “DetectChanges completed.” As a note, because these are new entities, even if something had changed, their state would still be Added.
After the context finishes detecting changes, it starts sending the SQL to the database. So next in the log are the special SQLite commands for the foreign keys setting, followed by the command to insert the magazine and return its new MagazineId.
Then the change tracker kicks in again, replacing the temporary value generated by the database for the MagazineId with the new database-generated value—fixing up first Magazine.MagazineId and then Article.MagazineId:
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10803]
Foreign key property 'Magazine.MagazineId' detected as changed from
'-2147482647' to '17' for entity with key '{MagazineId: 17}'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10803]
Foreign key property 'Article.MagazineId' detected as changed from
'-2147482647' to '17' for entity with key '{ArticleId:
-2147482647}'.
Now article has the correct foreign key value for MagazineId and the next log event is EF Core sending the SQL to insert the article into the database.
Finally, two more change tracking events are logged as EF Core revises the known state of both the magazine and the article it’s tracking to Unchanged:
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
The 'Magazine' entity with key '{MagazineId: 17}' tracked by
'PublicationsContext' changed from 'Added' to 'Unchanged'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
The 'Article' entity with key '{ArticleId: 17}' tracked by
'PublicationsContext' changed from 'Added' to 'Unchanged'.
I love seeing this laid out so clearly. Over the decade I’ve been working with Entity Framework, I’ve spent a lot of time debugging through code and digging very deeply through runtime debuggers and watch windows to understand how the change tracker works.
The ChangeTracking details for interacting with data coming from the database, especially if you modify and save it, are really impressive. Let’s look at that with a new method, GetAndUpdateSomeData in Figure 6, which retrieves a magazine with an article, makes an edit and then saves the changes. The method also writes out notices (“Query,” “Edit” and “Save”) so in the log I can see when I ran the query, when I made an edit and when I called SaveChanges.
Figure 6 A New Method for Exploring the Logging
private static void GetAndUpdateSomeData()
{
using (var context = new PublicationsContext())
{
Console.WriteLine("Query");
var mag = context.Magazines.Include(m=>m.Articles)
.FirstOrDefault(m => m.MagazineId == 1);
Console.WriteLine("Edit");
mag.Articles.FirstOrDefault().AuthorName += " and Friends";
Console.WriteLine("Save");
var results = context.SaveChanges();
Console.ForegroundColor = ConsoleColor.Red;
Console.WriteLine($"Program Message: The app has updated {results} rows");
}
I won’t list the entire log, but it first shows the SQL to query for the magazine with MagazineId 1. The log serves as a reminder that in EF Core, some Includes (notably for collections) are now broken down into separate queries on the database because it’s generally more efficient with respect to the size of the results and the effort of materializing the objects. After the magazine is returned, another event—that the context started tracking that Magazine—is displayed. Next, EF Core sends SQL to retrieve the articles for all of the magazines I filtered on, which will return only one article because that’s all the data I’ve got (just the one with MagazineId=1). The next event is that the context has started tracking that article entity. After this, there are two events indicating that the data reader was disposed—one for each of the two queries.
Now things get more interesting, as you can see in Figure 7, which shows most of the rest of the log.
Figure 7 ChangeTracking Logs During an Update
Edit
Save
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10800]
DetectChanges starting for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10802]
Unchanged 'Article.AuthorName' detected as changed from 'Julie Lerman' to
'Julie Lerman and Friends' and will be marked as modified
for entity with key '{ArticleId: 1}'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
The 'Article' entity with key '{ArticleId: 1}' tracked by
'PublicationsContext' changed from 'Unchanged' to 'Modified'.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10801]
DetectChanges completed for 'PublicationsContext'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
Executing DbCommand [Parameters=[], CommandType='Text',
CommandTimeout='30'] PRAGMA foreign_keys=ON;
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
Executing DbCommand [Parameters=[@p1='1' (DbType = String),
@p0='Julie Lerman and Friends' (Size = 24)], CommandType='Text',
CommandTimeout='30']
UPDATE "Article" SET "AuthorName" = @p0
WHERE "ArticleId" = @p1;
SELECT changes();
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807]
The 'Article' entity with key '{ArticleId: 1}' tracked by
'PublicationsContext' changed from 'Modified' to 'Unchanged'.
First notice my “Edit” message is followed directly by a “Save” message. Even though the context is currently tracking the article I’m editing, it has no way of updating state information in real time. It waits until the change tracker’s DetectChanges method is called, either explicitly in code or by another EF Core method such as SaveChanges. So it’s not until after I call SaveChanges that DetectChanges starts doing its job. The first thing it sees is that AuthorName has changed. The 18082 event relays that information and indicates that because of that change, it’s planning to mark its entity (the Article whose ArticleId is 1) as modified. The next event, 18087, states that it just changed that entity (ArticleId: 1) from Unchanged to Modified. This is amazing detail and when you’re debugging a problem or some unexpected behavior, it will be extremely helpful. I’m really grateful for this! (Hat tip to Arthur Vickers on the EF Team, as logging was his baby!)
After the change tracker finishes this work, you then see the update method. Again, the fact that I’ve enabled sensitive data is why you can see all of the parameters of the SQL command.
The “SELECT changes” at the end of the SQL is the SQLite way of returning the count of rows that were affected.
Finally, the change tracker cleans up the state of its tracked objects, marking the article as Unchanged and ready for its next adventure.
Don’t Forget About Other Logger Categories
It looks like I’d have to fill this magazine to show you the ins and outs of the other 10 DbLoggerCategory types that EF Core exposes. Now that you have a handle on how to expose that data, you can experiment with the different categories and see what kinds of information they share. Alternatively, you can just have EF Core spit out all of its logging data by defining a logging provider that doesn’t filter on anything. Rather than a predicate expression for the filter, just return true as I’ve done in this Too Much Information (TMI) factory:
public static readonly LoggerFactory TMIConsoleLoggerFactory
= new LoggerFactory(new[] {
new ConsoleLoggerProvider ((category, level) => true, false)
});
While logging is incredibly helpful for debugging problems, I think it’s equally important for gaining insight into how an API works. And the better you understand how it works, the less likely it is you’ll create problems that will need to be debugged.
Julie Lerman is a Microsoft Regional Director, Microsoft MVP, software team coach and consultant who lives in the hills of Vermont. You can find her presenting on data access and other topics at user groups and conferences around the world. She blogs at the thedatafarm.com/blog and is the author of “Programming Entity Framework,” as well as a Code First and a DbContext edition, all from O’Reilly Media. Follow her on Twitter: @julielerman and see her Pluralsight courses at bit.ly/PS-Julie.
Thanks to the following Microsoft technical expert for reviewing this article: Arthur Vickers