Ведение журнала и перехват операций базы данных

  • Статья

Примечание.

Только в EF6 и более поздних версиях. Функции, API и другие возможности, описанные на этой странице, появились в Entity Framework 6. При использовании более ранней версии могут быть неприменимы некоторые или все сведения.

Начиная с Entity Framework 6, в любое время Entity Framework отправляет команду в базу данных, которую эта команда может быть перехвачена кодом приложения. Это чаще всего используется для ведения журнала SQL, но также можно использовать для изменения или прерывания команды.

В частности, EF включает:

  • Свойство Log для контекста, аналогичного DataContext.Log в LINQ to SQL
  • Механизм настройки содержимого и форматирования выходных данных, отправляемых в журнал
  • Стандартные блоки низкого уровня для перехвата, что обеспечивает больший контроль и гибкость

Свойство Context Log

Свойство DbContext.Database.Log можно задать для делегата для любого метода, принимающего строку. Чаще всего он используется с любой текстовой машиной, задав его методу Write этого textWriter. Все SQL, созданные текущим контекстом, будут записаны в этот модуль записи. Например, следующий код записывает SQL в консоль:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    // Your code here...
}

Обратите внимание, что контекст. 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

(Обратите внимание, что это выходные данные, предполагающие, что инициализация базы данных уже произошла. Если инициализация базы данных еще не произошла, то будет гораздо больше выходных данных, показывающих все рабочие миграции, которые выполняются в рамках проверка для или создания новой базы данных.)

Что регистрируется?

Если для свойства log задано все из следующих элементов, будет зарегистрировано следующее:

  • SQL для всех различных видов команд. Пример:
    • Запросы, включая обычные запросы LINQ, запросы eSQL и необработанные запросы из таких методов, как SqlQuery
    • Вставка, обновление и удаление, созданные в рамках SaveChanges
    • Запросы загрузки связей, такие как запросы, созданные с помощью отложенной загрузки
  • Параметры
  • Выполняется ли команда асинхронно
  • Метка времени, указывающая, когда команда начала выполняться
  • Успешно ли выполнена команда, не удалось ли вызвать исключение или асинхронное выполнение команды было отменено.
  • Некоторые признаки значения результата
  • Приблизительное время выполнения команды. Обратите внимание, что это время от отправки команды до получения объекта результата обратно. Оно не включает время для чтения результатов.

Рассмотрим приведенный выше пример выходных данных, каждый из четырех команд, зарегистрированных в журнале:

  • Запрос, полученный из вызова контекста. Блоги.First
    • Обратите внимание, что метод ToString получения SQL не работал бы для этого запроса, так как "First" не предоставляет IQueryable, для которого можно вызвать ToString
  • Запрос, полученный из-за отложенной загрузки блога. Сообщения
    • Обратите внимание на сведения о параметре для значения ключа, для которого происходит отложенная загрузка
    • Регистрируются только свойства параметра, для которых заданы значения, не являющиеся значениями по умолчанию. Например, свойство Size отображается только в том случае, если оно не равно нулю.
  • Две команды, полученные из SaveChangesAsync; один для обновления, чтобы изменить название записи, другой для вставки, чтобы добавить новую запись
    • Обратите внимание, что сведения о параметрах свойств FK и Title
    • Обратите внимание, что эти команды выполняются асинхронно

Ведение журнала в разных местах

Как показано выше, ведение журнала в консоли очень просто. Кроме того, легко выполнять вход в память, файл и т. д. с помощью различных типов TextWriter.

Если вы знакомы с LINQ to SQL, вы можете заметить, что в LINQ to SQL свойство Log установлено для фактического объекта TextWriter (например, Console.Out), а в EF свойство Log задано метод, который принимает строку (например, Console.Write или Console.Out.Write). Причина этого заключается в том, чтобы отделить EF от TextWriter, принимая любой делегат, который может выступать в качестве приемника строк. Например, представьте, что у вас уже есть некоторые платформы ведения журнала, и он определяет метод ведения журнала, как показано ниже.

public class MyLogger
{
    public void Log(string component, string message)
    {
        Console.WriteLine("Component: {0} Message: {1} ", component, message);
    }
}

Это может быть подключено к свойству EF Log следующим образом:

var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);

Ведение журнала результатов

Текст команды журнала по умолчанию (SQL), параметры и строка "Выполнение" с меткой времени перед отправкой команды в базу данных. Строка "завершена", содержащая истекшее время, регистрируется после выполнения команды.

Обратите внимание, что для асинхронных команд строка "завершена" не регистрируется, пока асинхронная задача фактически завершается, завершается сбоем или отменяется.

Строка "завершена" содержит разные сведения в зависимости от типа команды и успешного выполнения.

Успешное выполнение

Для команд, которые успешно завершают выходные данные, является "Завершено в x мс с результатом: ", за которым следует некоторые признаки того, что был результат. Для команд, возвращающих средство чтения данных, указание результата — это тип возвращаемого dbDataReader . Для команд, возвращающих целочисленное значение, например команду обновления, показанную выше, отображается целое число.

Сбой выполнения

Для команд, которые завершаются сбоем, вызывая исключение, выходные данные содержат сообщение из исключения. Например, использование 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. Этот объект эффективно привязывает реализацию IDbCommandInterceptor (см. ниже) к делегату, который принимает строки и DbContext. Это означает, что методы 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)
    {
    }
}

Чтобы записать выходные данные, просто вызовите метод write, который будет отправлять выходные данные в настроенный делегат записи.

(Обратите внимание, что этот код упрощает удаление разрывов строк так же, как пример. Скорее всего, это не будет хорошо работать для просмотра сложного SQL.)

Настройка DatabaseLogFormatter

После создания нового класса DatabaseLogFormatter его необходимо зарегистрировать в EF. Это делается с помощью конфигурации на основе кода. В этом итоге создается новый класс, производный от DbConfiguration в той же сборке, что и класс DbContext, а затем вызывает SetDatabaseLogFormatter в конструкторе этого нового класса. Например:

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

Использование нового DatabaseLogFormatter

Теперь этот новый компонент DatabaseLogFormatter будет использоваться в любое время, когда задан Database.Log. Таким образом, выполнение кода из части 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 для регистрации SQL, созданного EF. Но этот код на самом деле является относительно тонким фасадом над некоторыми стандартными блоками низкого уровня для более общего перехвата.

Интерфейсы перехвата

Код перехвата основан на концепции интерфейсов перехвата. Эти интерфейсы наследуются от IDbInterceptor и определяют методы, которые вызываются при выполнении некоторых действий EF. Намерение состоит в том, чтобы один интерфейс для каждого типа перехватываемого объекта. Например, интерфейс IDbCommandInterceptor определяет методы, которые вызываются перед вызовом EF ExecuteNonQuery, ExecuteScalar, ExecuteReader и связанных методов. Аналогичным образом интерфейс определяет методы, которые вызываются при завершении каждой из этих операций. Класс DatabaseLogFormatter, который мы рассмотрели выше, реализует этот интерфейс для выполнения команд журнала.

Контекст перехвата

Глядя на методы, определенные на любом из интерфейсов перехватчика, очевидно, что каждый вызов получает объект типа DbInterceptionContext или какой-либо тип, производный от этого, например DbCommandInterceptionContext<>. Этот объект содержит контекстные сведения о действии, которое выполняет EF. Например, если действие выполняется от имени DbContext, то DbContext включается в dbInterceptionContext. Аналогичным образом для команд, выполняемых асинхронно, флаг IsAsync задается в DbCommandInterceptionContext.

Обработка результатов

Класс DbCommandInterceptionContext<> содержит свойства с именем Result, OriginalResult, Exception и OriginalException. Эти свойства имеют значение NULL/ноль для вызовов методов перехвата, которые вызываются перед выполнением операции , то есть для ... Выполнение методов. Если операция выполняется и завершается успешно, результат операции и результат операции заданы в качестве результата. Затем эти значения можно наблюдать в методах перехвата, которые вызываются после выполнения операции , т. е. на ... Выполненные методы. Аналогичным образом, если операция вызывается, будут заданы свойства Exception и OriginalException.

Подавление выполнения

Если перехватчик задает свойство Result перед выполнением команды (в одном из ... Методы выполнения) затем EF не попытается выполнить команду, но вместо этого будет использовать результирующий набор. Другими словами, перехватчик может подавлять выполнение команды, но ef продолжит выполнение, как если бы команда была выполнена.

Пример того, как это может использоваться, — это пакетная обработка команд, которая традиционно была выполнена с поставщиком упаковки. Перехватчик будет хранить команду для последующего выполнения как пакет, но будет "притворяться" EF, что команда выполнялась как обычная. Обратите внимание, что для реализации пакетной обработки требуется больше, но это пример того, как можно использовать изменение результата перехвата.

Выполнение также можно отключить, задав свойство Exception в одном из ... Выполнение методов. Это приводит к тому, что EF будет продолжаться, как если бы выполнение операции завершилось сбоем, вызвав заданное исключение. Это может, конечно, привести к сбою приложения, но это также может быть временное исключение или другое исключение, которое обрабатывается EF. Например, это можно использовать в тестовых средах для проверки поведения приложения при сбое выполнения команды.

Изменение результата после выполнения

Если перехватчик задает свойство Result после выполнения команды (в одном из ... Выполненные методы) затем EF будет использовать измененный результат вместо результата, который был фактически возвращен из операции. Аналогичным образом, если перехватчик задает свойство Exception после выполнения команды, EF вызовет исключение набора, как если бы операция выдала исключение.

Перехватчик также может задать для свойства Exception значение NULL, чтобы указать, что исключение не должно быть создано. Это может быть полезно, если выполнение операции завершилось сбоем, но перехватчик хочет EF продолжить, как если бы операция завершилась успешно. Обычно это также включает настройку результата, чтобы EF имеет некоторое значение результата для работы с ним по мере продолжения.

OriginalResult и OriginalException

После выполнения операции EF он установит свойства Result и OriginalResult, если выполнение не завершилось сбоем, или свойства Exception и OriginalException, если выполнение завершилось сбоем.

Свойства OriginalResult и OriginalException доступны только для чтения и задаются EF только после выполнения операции. Эти свойства нельзя задать перехватчиками. Это означает, что любой перехватчик может различать исключение или результат, заданный другим перехватчиком в отличие от реального исключения или результата, которое произошло при выполнении операции.

Регистрация перехватчиков

После создания класса, реализующего один или несколько интерфейсов перехвата, его можно зарегистрировать в EF с помощью класса DbInterception. Например:

DbInterception.Add(new NLogCommandInterceptor());

Перехватчики также можно зарегистрировать на уровне домена приложения с помощью механизма конфигурации на основе кода DbConfiguration.

Пример. Ведение журнала в NLog

Давайте поместим все это в пример, в который используется IDbCommandInterceptor и NLog :

  • Зайдите в журнал предупреждение для любой команды, которая выполняется не асинхронно
  • Зайдите в журнал ошибки для любой команды, которая вызывается при выполнении

Ниже приведен класс, который выполняет ведение журнала, который должен быть зарегистрирован, как показано выше:

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);
        }
    }
}

Обратите внимание, что этот код использует контекст перехвата для обнаружения выполнения команды, не асинхронной и обнаружения ошибки при выполнении команды.