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:


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

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 Log(string component, string message)

    {

        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.

转载:https://blog.oneunicorn.com/2013/05/08/ef6-sql-logging-part-1-simple-logging/



EntityFramework 日志记录

来自为知笔记(Wiz)

时间: 2024-10-14 00:58:59

EF6 SQL Logging – Part 1: Simple Logging | One Unicorn的相关文章

slf4j(simple logging facade for java)

http://www.tuicool.com/articles/IfeUfq slf4j(simple logging facade for java)是Java的简单的日志门面,它 不是具体的日志解决方案,它只服务于各种各样 slf4j-logo 的 日志系统.这里的slf4j-logo可以是log4j,可以是jdk的日志,可以是logback,还可以是slf4j-simple等 等.按照官方的说法,SLF4J是一个用于日志系统的简单Facade,允许最终用户在部署其应用时使用其所希望的日志系

EF6 SQL Logging – Part 3: Interception building blocks | One Unicorn

In parts 1 and 2 of this series we looked at how to use DbContext.Database.Log to log the SQL generated by EF. But this code is actually a relatively thin fa?ade over some low-level building blocks for interception in general and, in this case, DbCom

EF6 SQL Logging – Part 2: Changing the content/formatting | One Unicorn

In part 1 we saw how DbContext.Database.Log can be used to easily log SQL to the console or some other TextWriter. This post covers how the context and formatting of the output can be changed. DatabaseLogFormatter Under the covers the Database.Log pr

工作流引擎Activiti 专题

https://github.com/Activiti/Activiti Quick Start Guide This quick start assumes: Familiarity with Maven and Java A development environment with Java The following variables will be referenced in this tutorial Variable Description $mvnProject The root

How to setup SLF4J and LOGBack in a web app - fast--转载

原文:https://wiki.base22.com/display/btg/How+to+setup+SLF4J+and+LOGBack+in+a+web+app+-+fast Logback is intended as a successor to the popular log4j project. It was designed, in addition to many individual contributors, by Ceki Gülcü, the founder of log

python logging 配置

在python中,logging由logger,handler,filter,formater四个部分组成,logger是提供我们记录日志的方法:handler是让我们选择日志的输出地方,如:控制台,文件,邮件发送等,一个logger添加多个handler:filter是给用户提供更加细粒度的控制日志的输出内容:formater用户格式化输出日志的信息.python中配置logging有三种方式第一种:基础配置,logging.basicConfig(filename="config.log&q

Taxonomy of class loader problems encountered when using Jakarta Commons Logging(转)

Acknowledgments I would like to thank Jacob Kjome for reviewing early drafts of this document. His comments helped to clarify several important points. Jake also keeps reminding us on the log4j-dev mailing list that the child-parent delegation model

Common.Logging log4net Common.Logging.Log4Net 配置

1.log4net 单独配置 log4net支持多种格式的日志输出,我这里只配置输出到本地的txt文件这种格式. <log4net> <root> <appender-ref ref="RollingFileAppender" /> </root> <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppende

【改变mysql 日志位置Bug】Could not use mysql.log for logging (error 13)

今天手贱,看到mysql 的日志在/var/log/mysql下面.总是觉得别扭,于是就想改变日志的位置, 本人开发环境 vagrant  + ubuntu12.04 ,在/etc/mysql/mysql中修改了general_log的位置,放在/data/logs/mysql下面 然后重启服务,service mysql restart 查看错误日志发现说 /usr/sbin/mysqld: File '/data/logs/mysql/mysql.log' not found (Errcod