데이터베이스 작업 로깅 및 인터셉션
참고 항목
EF6 이상만 - 이 페이지에서 다루는 기능, API 등은 Entity Framework 6에 도입되었습니다. 이전 버전을 사용하는 경우 이 정보의 일부 또는 전체가 적용되지 않습니다.
Entity Framework 6부터는 Entity Framework가 데이터베이스에 명령을 보낼 때마다 애플리케이션 코드에서 이 명령을 가로챌 수 있습니다. 이는 SQL 로깅에 가장 일반적으로 사용되지만 명령을 수정하거나 중단하는 데 사용할 수도 있습니다.
특히 EF에는 다음이 포함됩니다.
- LINQ to SQL에서 DataContext.Log와 유사한 컨텍스트에 대한 로그 속성
- 로그에 전송된 출력의 콘텐츠 및 서식을 사용자 지정하는 메커니즘
- 더 큰 제어/유연성을 제공하는 인터셉션을 위한 낮은 수준의 구성 요소
컨텍스트 로그 속성
DbContext.Database.Log 속성은 문자열을 사용하는 모든 메서드에 대한 대리자로 설정할 수 있습니다. 가장 일반적으로 해당 TextWriter의 "쓰기" 메서드로 설정하여 TextWriter와 함께 사용됩니다. 현재 컨텍스트에서 생성된 모든 SQL은 해당 기록기에 기록됩니다. 예를 들어 다음 코드는 SQL을 콘솔에 기록합니다.
using (var context = new BlogContext())
{
context.Database.Log = Console.Write;
// Your code here...
}
context.Database.Log가 Console.Write로 설정되어 있습니다. 이는 SQL을 콘솔에 기록하는 데 필요한 모든 설정입니다.
일부 출력을 볼 수 있도록 몇 가지 간단한 쿼리/삽입/업데이트 코드를 추가해 보겠습니다.
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.SaveChanges();
}
그러면 다음 출력이 생성됩니다.
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 10/8/2013 10:55:41 AM -07:00
-- 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 10/8/2013 10:55:41 AM -07:00
-- 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 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 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 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader
(데이터베이스 초기화가 이미 발생했다고 가정하는 출력입니다. 데이터베이스 초기화가 아직 발생하지 않은 경우 마이그레이션이 새 데이터베이스를 확인하거나 만들기 위해 수행하는 모든 작업을 보여주는 더 많은 출력이 있습니다.)
무엇이 기록되나요?
로그 속성이 설정되면 다음이 모두 기록됩니다.
- 모든 종류의 명령에 대한 SQL 예:
- 일반 LINQ 쿼리, eSQL 쿼리 및 SqlQuery와 같은 메서드의 원시 쿼리를 포함한 쿼리
- SaveChanges의 일부로 생성된 삽입, 업데이트 및 삭제
- 지연 로드로 생성된 쿼리와 같은 관계 로드 쿼리
- 매개 변수
- 명령이 비동기적으로 실행되는지 여부
- 명령이 실행되기 시작한 시기를 나타내는 타임스탬프
- 명령이 성공적으로 완료되었는지, 예외를 throw하여 실패했는지 또는 비동기의 경우 취소되었는지 여부
- 결과 값의 일부 표시
- 명령을 실행하는 데 걸린 대략적인 시간입니다. 명령을 보내는 시간부터 결과 개체를 다시 가져오는 시간입니다. 결과를 읽는 시간은 포함되지 않습니다.
위의 예제 출력을 살펴보면 기록된 네 가지 명령은 각각 다음과 같습니다.
- context.Blogs.First 호출로 인한 쿼리
- "First"는 ToString을 호출할 수 있는 IQueryable을 제공하지 않으므로 SQL을 가져오는 ToString 메서드는 이 쿼리에 대해 작동하지 않습니다.
- blog.Posts의 지연 로드로 인한 쿼리 결과
- 지연 로드가 발생하는 키 값에 대한 매개 변수 세부 정보를 확인합니다.
- 기본값이 아닌 값으로 설정된 매개 변수의 속성만 기록됩니다. 예를 들어 크기 속성은 0이 아닌 경우에만 표시됩니다.
- SaveChangesAsync에서 생성된 두 개의 명령(게시물 제목을 변경하는 업데이트용 및 새 게시물을 추가하는 삽입용)
- FK 및 Title 속성에 대한 매개 변수 세부 정보를 확인합니다.
- 이러한 명령이 비동기적으로 실행되고 있습니다.
다른 위치에 로깅
위와 같이 콘솔에 로깅하는 것은 매우 쉽습니다. 또한 다양한 종류의 TextWriter를 사용하여 메모리, 파일 등에 쉽게 로그할 수 있습니다.
LINQ to SQL에 익숙한 경우 LINQ to SQL에서는 로그 속성이 실제 TextWriter 개체(예: Console.Out)로 설정되고 EF에서는 로그 속성이 문자열을 허용하는 메서드(예: Console.Write 또는 Console.Out.Write)로 설정된다는 것을 알 수 있습니다. 이는 문자열의 싱크 역할을 할 수 있는 대리자를 수락하여 TextWriter에서 EF를 분리하기 위해서입니다. 예를 들어 이미 일부 로깅 프레임워크가 있고 다음과 같이 로깅 메서드를 정의한다고 상상해 보세요.
public class MyLogger
{
public void Log(string component, string message)
{
Console.WriteLine("Component: {0} Message: {1} ", component, message);
}
}
다음과 같은 EF 로그 속성에 연결할 수 있습니다.
var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);
결과 로깅
기본 로거는 명령 텍스트(SQL), 매개 변수 및 명령이 데이터베이스로 전송되기 전에 타임스탬프가 있는 "실행 중" 줄을 기록합니다. 명령 실행 후 경과된 시간을 포함하는 "완료됨" 줄이 기록됩니다.
비동기 명령의 경우 비동기 작업이 실제로 완료, 실패 또는 취소될 때까지 "완료됨" 줄이 기록되지 않습니다.
"완료됨" 줄에는 명령 유형 및 실행 성공 여부에 따라 다른 정보가 포함됩니다.
성공한 실행
성공적으로 완료된 명령의 경우 출력은 "다음 결과와 함께 xms에서 완료됨: " 다음에 결과 내용을 보여줍니다. 데이터 판독기를 반환하는 명령의 경우 결과 표시는 반환된 DbDataReader 형식입니다. 위에 표시된 업데이트 명령과 같은 정수 값을 반환하는 명령의 경우 표시되는 결과는 해당 정수입니다.
실패한 실행
예외를 throw하여 실패하는 명령의 경우 출력에는 예외의 메시지가 포함됩니다. 예를 들어 SqlQuery를 사용하여 존재하는 테이블에 대해 쿼리하면 다음과 같은 로그 출력이 발생합니다.
SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.
취소된 실행
작업이 취소된 비동기 명령의 경우 취소하려고 할 때 이는 기본 ADO.NET 공급자가 자주 수행하는 작업이기 때문에 예외로 인해 결과가 실패할 수 있습니다. 이러한 문제가 발생하지 않고 작업이 완전히 취소된 경우 출력은 다음과 같이 표시됩니다.
update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms
로그 콘텐츠 변경 및 서식 지정
아래의 Database.Log 속성은 DatabaseLogFormatter 개체를 사용합니다. 이 개체는 문자열 및 DbContext를 허용하는 대리자(아래 참조)에 IDbCommandInterceptor 구현을 효과적으로 바인딩합니다. 즉, DatabaseLogFormatter의 메서드는 EF에서 명령을 실행하기 전과 후에 호출됩니다. 이러한 DatabaseLogFormatter 메서드는 로그 출력을 수집하고 형식을 지정하여 대리자에게 보냅니다.
DatabaseLogFormatter 사용자 지정
DatabaseLogFormatter에서 파생되고 메서드를 적절하게 재정의하는 새 클래스를 만들어 로깅된 내용 및 형식 변경 방법을 변경할 수 있습니다. 재정의하는 가장 일반적인 방법은 다음과 같습니다.
- LogCommand – 명령을 실행하기 전에 로깅하는 방법을 변경하려면 이를 재정의합니다. 기본적으로 LogCommand는 각 매개 변수에 대해 LogParameter를 호출하며, 재정의에서 동일한 작업을 수행하거나 매개 변수를 다르게 처리하도록 선택할 수 있습니다.
- LogResult – 명령 실행에서 결과가 기록되는 방식을 변경하려면 이를 재정의합니다.
- LogParameter – 매개 변수 로깅의 서식 지정 및 콘텐츠를 변경하려면 이를 재정의합니다.
예를 들어 각 명령이 데이터베이스로 전송되기 전에 한 줄만 기록하려고 하는 경우를 가정해 보겠습니다. 이 작업은 다음의 두 재정의를 사용하여 수행할 수 있습니다.
- LOGCommand를 재정의하여 SQL의 한 줄 서식 지정 및 작성
- 아무 작업도 수행하지 않도록 LogResult 재정의
코드는 다음과 비슷합니다.
public class OneLineFormatter : DatabaseLogFormatter
{
public OneLineFormatter(DbContext context, Action<string> writeAction)
: base(context, writeAction)
{
}
public override void LogCommand<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
Write(string.Format(
"Context '{0}' is executing command '{1}'{2}",
Context.GetType().Name,
command.CommandText.Replace(Environment.NewLine, ""),
Environment.NewLine));
}
public override void LogResult<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
}
}
출력을 기록하려면 구성된 쓰기 대리자에게 출력을 보내는 쓰기 메서드를 호출하기만 하면 됩니다.
(이 코드는 예제와 같이 줄 바꿈을 간단하게 제거합니다.) 이는 복잡한 SQL 확인에는 제대로 작동하지 않을 수 있습니다.)
DatabaseLogFormatter 설정
새 DatabaseLogFormatter 클래스가 만들어지면 EF에 등록해야 합니다. 이 작업은 코드 기반 구성을 사용하여 수행됩니다. 즉, DbContext 클래스와 동일한 어셈블리의 DbConfiguration에서 파생되는 새 클래스를 만든 다음 이 새 클래스의 생성자에서 SetDatabaseLogFormatter를 호출합니다. 예시:
public class MyDbConfiguration : DbConfiguration
{
public MyDbConfiguration()
{
SetDatabaseLogFormatter(
(context, writeAction) => new OneLineFormatter(context, writeAction));
}
}
새 DatabaseLogFormatter 사용
이제 Database.Log가 설정될 때마다 이 새 DatabaseLogFormatter가 사용됩니다. 따라서 1부에서 코드를 실행하면 다음과 같은 출력이 생성됩니다.
Context 'BlogContext' is executing command '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)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'
인터셉션 구성 요소
지금까지 DbContext.Database.Log를 사용하여 EF에서 생성된 SQL을 기록하는 방법을 살펴보았습니다. 그러나 이 코드는 실제로 좀 더 일반적인 인터셉션을 위해 일부 낮은 수준의 구성 요소에 비해 비교적 얇은 외관입니다.
인터셉션 인터페이스
인터셉션 코드는 인터셉션 인터페이스의 개념을 중심으로 빌드됩니다. 이러한 인터페이스는 IDbInterceptor에서 상속되며 EF가 일부 작업을 수행할 때 호출되는 메서드를 정의합니다. 해당 목적은 가로채는 개체 유형당 하나의 인터페이스를 갖는 것입니다. 예를 들어 IDbCommandInterceptor 인터페이스는 EF가 ExecuteNonQuery, ExecuteScalar, ExecuteReader 및 관련 메서드를 호출하기 전에 호출되는 메서드를 정의합니다. 마찬가지로 인터페이스는 이러한 각 작업이 완료되면 호출되는 메서드를 정의합니다. 위에서 살펴본 DatabaseLogFormatter 클래스는 이 인터페이스를 구현하여 명령을 기록합니다.
인터셉션 컨텍스트
인터셉션 인터페이스에 정의된 메서드를 살펴보면 모든 호출에 DbInterceptionContext 형식의 개체 또는 DbCommandInterceptionContext<>와 같은 형식에서 파생된 일부 형식이 제공됩니다. 이 개체에는 EF가 수행하는 작업에 대한 컨텍스트 정보가 포함되어 있습니다. 예를 들어 작업이 DbContext를 대신하여 수행되는 경우 DbContext는 DbInterceptionContext에 포함됩니다. 마찬가지로 비동기적으로 실행되는 명령의 경우 IsAsync 플래그는 DbCommandInterceptionContext에 설정됩니다.
결과 처리
DbCommandInterceptionContext<> 클래스에는 결과, OriginalResult, 예외 및 OriginalException이라는 속성이 포함되어 있습니다. 이러한 속성은 작업이 실행되기 전에 호출되는 인터셉션 메서드, 즉 ...실행 메서드에 대한 호출의 경우 null/0으로 설정됩니다. 작업이 실행되고 성공하면 결과 및 OriginalResult가 작업의 결과로 설정됩니다. 그런 다음, 작업이 실행된 후 호출되는 인터셉션 메서드, 즉 ...실행된 메서드에서 이러한 값을 관찰할 수 있습니다. 마찬가지로 작업이 throw되면 예외 및 OriginalException 속성이 설정됩니다.
실행 표시 안 함
인터셉터에서 명령이 실행되기 전에 결과 속성을 설정하는 경우(...실행 메서드 중 하나에서) EF는 실제로 명령을 실행하려고 시도하지 않고 대신 결과 집합만 사용합니다. 즉, 인터셉터에서 명령 실행을 표시하지 않을 수 있지만 EF는 명령이 실행된 것처럼 계속 진행됩니다.
이를 사용하는 방법의 예는 일반적으로 래핑 공급자를 사용하여 수행된 명령 일괄 처리입니다. 인터셉터에서는 이후 실행을 위해 명령을 일괄 처리로 저장하지만 EF는 명령이 정상적으로 실행된 “것처럼” 진행됩니다. 일괄 처리를 구현하려면 이보다 더 많은 것이 필요하지만 인터셉터 결과를 변경하는 방법의 예입니다.
...실행 메서드 중 하나에서 예외 속성을 설정하여 실행을 표시하지 않을 수도 있습니다. 그러면 EF는 지정된 예외를 throw하여 작업 실행이 실패한 것처럼 계속 진행됩니다. 물론 이로 인해 애플리케이션이 충돌할 수 있지만 일시적인 예외 또는 EF에서 처리하는 다른 예외일 수도 있습니다. 예를 들어 이는 테스트 환경에서 명령 실행이 실패할 때 애플리케이션의 동작을 테스트하는 데 사용할 수 있습니다.
실행 후 결과 변경
인터셉터에서 명령이 실행된 후 결과 속성을 설정하는 경우(... 실행된 메서드 중 하나에서) EF는 작업에서 실제로 반환된 결과 대신 변경된 결과를 사용합니다. 마찬가지로 인터셉터에서 명령이 실행된 후 예외 속성을 설정하는 경우 EF는 작업에서 예외를 throw한 것처럼 설정된 예외를 throw합니다.
인터셉터에서 예외 속성을 null로 설정하여 예외를 throw해서는 안 된다는 것을 나타낼 수도 있습니다. 이는 작업 실행이 실패했지만 인터셉터에서 EF가 작업이 성공한 것처럼 계속 진행되기를 원하는 경우에 유용할 수 있습니다. 여기에는 일반적으로 EF에서 계속 작업할 결과 값을 갖도록 하는 결과 설정도 포함됩니다.
OriginalResult 및 OriginalException
EF가 작업을 실행한 후에는 실행이 실패하지 않은 경우 결과 및 OriginalResult 속성 또는 예외와 함께 실행이 실패한 경우 예외 및 OriginalException 속성을 설정합니다.
OriginalResult 및 OriginalException 속성은 읽기 전용이며 실제로 작업을 실행한 후에만 EF에서 설정합니다. 이러한 속성은 인터셉터에서 설정할 수 없습니다. 즉, 모든 인터셉터에서 작업이 실행될 때 발생한 실제 예외 또는 결과와 달리 다른 인터셉터에서 설정한 예외 또는 결과를 구분할 수 있습니다.
인터셉터 등록
하나 이상의 인터셉션 인터페이스를 구현하는 클래스가 만들어지면 DbInterception 클래스를 사용하여 EF에 등록할 수 있습니다. 예시:
DbInterception.Add(new NLogCommandInterceptor());
인터셉터는 DbConfiguration 코드 기반 구성 메커니즘을 사용하여 앱 도메인 수준에서 등록할 수도 있습니다.
예: NLog에 로깅
IDbCommandInterceptor 및 NLog를 사용하는 다음 예제로 이 모든 것을 정리해 보겠습니다.
- 비동기적으로 실행되는 명령에 대한 경고 기록
- 실행할 때 throw되는 명령에 대한 오류 기록
위와 같이 등록해야 하는 로깅을 수행하는 클래스는 다음과 같습니다.
public class NLogCommandInterceptor : IDbCommandInterceptor
{
private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
public void NonQueryExecuting(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void NonQueryExecuted(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
LogIfError(command, interceptionContext);
}
public void ReaderExecuting(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void ReaderExecuted(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
LogIfError(command, interceptionContext);
}
public void ScalarExecuting(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void ScalarExecuted(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
LogIfError(command, interceptionContext);
}
private void LogIfNonAsync<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
if (!interceptionContext.IsAsync)
{
Logger.Warn("Non-async command used: {0}", command.CommandText);
}
}
private void LogIfError<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
if (interceptionContext.Exception != null)
{
Logger.Error("Command {0} failed with exception {1}",
command.CommandText, interceptionContext.Exception);
}
}
}
이 코드가 인터셉션 컨텍스트를 사용하여 명령이 비동기적으로 실행되는 시기를 검색하고 명령을 실행하는 동안 오류가 발생한 경우를 검색하는 방법을 알아봅니다.
.NET