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

Примечание

Только в 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
    • Запросы загрузки связей, такие как запросы, созданные отложенной загрузкой
  • Параметры
  • Выполняется ли команда асинхронно
  • Метка времени, указывающая, когда команда начала выполняться
  • Была ли команда выполнена успешно, не удалось создать исключение или отменить асинхронную операцию.
  • Некоторые признаки значения результата
  • Приблизительное время выполнения команды. Обратите внимание, что это время от отправки команды к получению объекта результата обратно. Оно не включает время для чтения результатов.

В приведенном выше примере выходных данных регистрируются следующие четыре команды:

  • Запрос, полученный из вызова контекста. Blogs.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 следующим образом:

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 или ноль для вызовов методов перехвата, которые вызываются перед выполнением операции, то есть для ... Выполнение методов. Если операция выполняется и завершается успешно, для результата операции задается результат операции Result и OriginalResult. Затем эти значения можно наблюдать в методах перехвата, которые вызываются после выполнения операции, т. е. на ... Выполненные методы. Аналогичным образом, если операция вызывается, будут заданы свойства Exception и OriginalException.

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

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

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

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

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

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

Перехватчик также может присвоить свойству 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);
        }
    }
}

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