EF6 SQL Logging – Part 1: Simple Logging | One Unicorn

Posted 2020-07-09 在云端仰望星空

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了EF6 SQL Logging – Part 1: Simple Logging | One Unicorn相关的知识，希望对你有一定的参考价值。

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:

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: SqlDataReader

SELECT
[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: SqlDataReader

update [dbo].[Posts]
set [Title] = @0
where ([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: 1

insert [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:

The query resulting from the call to context.Blogs.First
- 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
The query resulting from the lazy-loading of blog.Posts
- 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.
Two commands resulting from SaveChangesAsync; one for the update to change a post title, the other for an insert to add a new post
- Notice the parameter details for the FK and Title properties
- Notice that these commands are being executed asynchronously