On the EF team we made a late decision to add some support for interception and logging of generated SQL in EF6. To this end recent checkins have added support for:
- A Log property for the context similar to DataContext.Log in LINQ to SQL
- A mechanism to customize the content and formatting of the output sent to the log
- Low-level building blocks for interception giving greater control/flexibility
(Note that most of what is described here came in too late and is therefore
not part of the beta 1 release. Instead you can try it out using a recent
nightly build and it will be included in the upcoming RC release.)
Context Log property
The DbContext.Database.Log property can be set to a delegate for any method that takes a string. In particular, it can be used with any TextWriter by setting it to the “Write” method of that TextWriter. All SQL generated by the current context will be logged
to that writer. For example, the following code will log SQL to the console:
|
1
2
3
4
5
6
|
using (var context = new BlogContext()){ context.Database.Log = Console.Write; // Your code here...} |
Notice that context.Database.Log is set to Console.Write. This is all that is needed to log SQL to the console.
Let’s add some simple query/insert/update code so that we can see some output:
|
1
2
3
4
5
6
7
8
9
10
11
12
|
using (var context = new BlogContext()){ context.Database.Log = Console.Write; var blog = context.Blogs.First(b => b.Title == "One Unicorn"); blog.Posts.First().Title = "Green Eggs and Ham"; blog.Posts.Add(new Post { Title ="I do not like them!"}); context.SaveChangesAsync().Wait();} |
At the time of writing this will generate the following output, although we may change this format before EF6 is released:
SELECT TOP (1)[Extent1].[Id] AS [Id],[Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)-- Executing at 5/13/2013 10:19:04 AM-- Completed in 4 ms with result: SqlDataReaderSELECT[Extent1].[Id]
AS [Id],[Extent1].[Title] AS [Title],[Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1-- EntityKeyValue1: '1' (Type = Int32)-- Executing at 5/13/2013 10:19:04 AM-- Completed in 2 ms with result: SqlDataReaderupdate
[dbo].[Posts]set [Title] = @0where ([Id] = @1)-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)-- @1: '1' (Type = Int32)-- Executing asynchronously at 5/13/2013 10:19:04 AM-- Completed in 11 ms with result: 1insert [dbo].[Posts]([Title], [BlogId])values
(@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()-- @0: 'I do not like them!' (Type = String, Size = -1)-- @1: '1' (Type = Int32)-- Executing asynchronously at 5/13/2013 10:19:04 AM-- Completed in 2 ms with result: SqlDataReader
(Note that this is the output assuming any database initialization has already happened. If database initialization had not already happened then there would be a lot more output showing all the work Migrations does under the covers to check for or create
a new database.)
What gets logged
When the Log property is set all of the following will be logged:
- SQL for all different kinds of commands. For example:
- Queries, including normal LINQ queries, eSQL queries, and raw queries from methods such as SqlQuery
- Inserts, updates, and deletes generated as part of SaveChanges
- Relationship loading queries such as those generated by lazy loading
- Parameters
- Whether or not the command is being executed asynchronously
- A timestamp indicating when the command started executing
- Whether or not the command completed successfully, failed by throwing an exception, or, for async, was canceled
- Some indication of the result value
- The approximate amount of time it took to execute the command
Looking at the example output above, each of the four commands logged are:
- Notice that the ToString method of getting the SQL would not have worked for this query since “First” does not provide an IQueryable on which ToString could be called
- Notice the parameter details for the key value for which lazy loading is happening
- Only properties of the parameter that are set to non-default values are logged. For example, the Size property is only shown if it is non-zero.
- Notice the parameter details for the FK and Title properties
- Notice that these commands are being executed asynchronously
Logging to different places
As shown above logging to the console is super easy. It’s also easy to log to memory, file, etc. by using different kinds of TextWriter. Damien Guard wrote
a post on this for the LINQ to SQL Log property which also applies to the new property in EF.
If you are familiar with LINQ to SQL (or have looked at the link above) you might notice that in LINQ to SQL the Log property is set to the actual TextWriter object (e.g. Console.Out) while in EF the Log property is set to a method that accepts a string
(e.g. Console.Write or Console.Out.Write). The reason for this is that EF is decouple from TextWriter by accepting any delegate that can act as a sink for strings. For example, imagine that you already have some logging framework and it defines a logging method
like so:
|
1
2
3
4
5
6
7
|
public class MyLogger{ public static void string component, string { Console.WriteLine("Component: {0} Message: {1} ", component, message); }} |
This could be hooked up to the EF Log property like this:
|
1
|
context.Database.Log = s => logger.Log("EFApp", s); |
It’s worth keeping two things in mind here:
- If all you need to do is control the format and content of the strings that are logged then this can be done while still hooking the Log property to a TextWriter in a simple way. See
part 2 of this series for details. - In part 3 of this series we’ll look at a lower-level way to log directly to something that isn’t a TextWriter without using Log at all.
Result logging
The default logger logs command text (SQL), parameters, and the “Executing” line with a timestamp before the command is sent to the database. A “completed” line containing elapsed time is logged following execution of the command.
Note that for async commands the “completed” line is not logged until the async task actually completes, fails, or is canceled.
The “completed” line contains different information depending on the type of command and whether or not execution was successful.
Successful execution
For commands that complete successfully the output is “Completed in x ms with result: “ followed by some indication of what the result was. For commands that return a data reader the result indication is the type of DbDataReader returned. For commands that
return an integer value such as the update command shown above the result shown is that integer.
Failed execution
For commands that fail by throwing an exception, the output contains the message from the exception. For example, using SqlQuery to query against a table that does exit will result in log output something like this:
SELECT * from ThisTableIsMissing-- Executing at 5/13/2013 10:19:05 AM-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.
Canceled execution
For async commands where the task is canceled the result could be failure with an exception, since this is what the underlying ADO.NET provider often does when an attempt is made to cancel. If this doesn’t happen and the task is canceled cleanly then the
output will look something like this:
update Blogs set Title = 'No' where Id = -1-- Executing asynchronously at 5/13/2013 10:21:10 AM-- Canceled in 1 ms
But I want something different!
It has been apparent from discussions among just a few members of the EF team that different people have different opinions on what the log output should contain and how it should be formatted. The default (which may change before we release so please provide
feedback about what you like and don’t like) is an attempt to provide commonly useful information in an easy-to-read format. However, it is easy to change this output if you want something different. I will cover how to do this in my next post. In a further
post I will also cover the lower-level interception hooks that allow more flexible control over what happens when commands are executed.