Высокопроизводительное логирование в .NET

Для сценариев ведения журнала с высокой производительностью в .NET 6 и более поздних версиях используйте LoggerMessageAttributeгенерацию исходного кода во время компиляции. Такой подход обеспечивает оптимальную производительность, устраняя упаковку, временные выделения и разбор шаблона сообщений во время выполнения.

Ведение журнала, созданное источником, обеспечивает следующие преимущества производительности по сравнению с методами расширения средства ведения журнала, такими как LogInformation и LogDebug:

• Устраняет боксинг: Методам расширения ведения журнала требуется "боксинг" (преобразование) типов значений, таких как int, в object. Логгирование, генерируемое источником, избегает боксинга благодаря использованию строго типизированных параметров.
• Анализ шаблонов во время компиляции: Методы расширения для ведения журналов должны анализировать шаблон сообщения (именованную строку формата) каждый раз, когда записывается сообщение журнала. Логирование, генерируемое источником, анализирует шаблоны один раз во время компиляции.
• Уменьшает выделение: Генератор источников создает оптимизированный код, который сводит к минимуму выделение объектов и временное использование памяти.

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

Подсказка

Весь пример исходного кода для ведения журнала доступен для загрузки в Обозревателе примеров. Дополнительные сведения см. в разделе Обзор примеров кода: ведение журнала в .NET.

Определите сообщения логгера с использованием генерации источника.

Чтобы создать сообщения журнала высокой производительности в .NET 6 и более поздних версиях, определите partial методы, аннотированные LoggerMessageAttribute. Генератор источника создает реализацию во время компиляции.

Базовый метод ведения журнала

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

public static partial class Log
{
    [LoggerMessage(
        EventId = 13,
        Level = LogLevel.Critical,
        Message = "Epic failure processing item!")]
    public static partial void FailedToProcessWorkItem(
        ILogger logger, Exception ex);
}

Шаблон сообщения использует заполнители, заполненные параметрами метода. Имена заполнителей должны быть описательными и согласованными для шаблонов. Они служат именами свойств в структурированных данных журнала. Мы рекомендуем использовать стиль Pascal для имен заполнителей. Например, {Item}, {DateTime}.

Вызовите метод ведения журнала из кода. Например, при возникновении исключения во время обработки рабочих элементов:

try
{
    // Process work item.
}
catch (Exception ex)
{
    Log.FailedToProcessWorkItem(logger, ex);
}

Этот код создает выходные данные консоли, такие как:

crit: WorkerServiceOptions.Example.Worker[13]
      Epic failure processing item!
      System.Exception: Failed to verify communications.

Логирование с параметрами

Чтобы передать параметры в сообщение журнала, добавьте их в качестве параметров метода. Имена параметров соответствуют заполнителям в шаблоне сообщения:

public static partial class Log
{
    [LoggerMessage(
        EventId = 1,
        Level = LogLevel.Information,
        Message = "Processing priority item: {Item}")]
    public static partial void PriorityItemProcessed(
        ILogger logger, WorkItem item);
}

Вызовите метод с логгером и значениями параметров.

var workItem = queue.Dequeue();
Log.PriorityItemProcessed(logger, workItem);

Этот код создает выходные данные консоли, такие как:

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

Структурированные хранилища журналов могут использовать имя события при наличии идентификатора события для улучшения ведения журнала. Например, Serilog использует имя события.

Определите область сообщения логгера с генерацией исходного кода

Области журналов можно определить для упаковки ряда сообщений журнала с дополнительным контекстом. При использовании ведения журнала, созданного источником, вы объединяете LoggerMessageAttribute методы со стандартным ILogger.BeginScope методом.

Включите IncludeScopes в разделе средства ведения журнала консоли appsettings.json:

{
    "Logging": {
        "Console": {
            "IncludeScopes": true
        },
        "LogLevel": {
            "Default": "Information",
            "Microsoft": "Warning",
            "Microsoft.Hosting.Lifetime": "Information"
        }
    }
}

Создайте методы ведения журнала, созданные источником, и заключите их в область с помощью BeginScope:

public static partial class Log
{
    [LoggerMessage(
        EventId = 1,
        Level = LogLevel.Information,
        Message = "Processing priority item: {Item}")]
    public static partial void PriorityItemProcessed(
        ILogger logger, WorkItem item);
}

Используйте метод ведения журнала в области в коде приложения:

using (_logger.BeginScope("Processing scope, started at: {DateTime}", DateTime.Now))
{
    Log.PriorityItemProcessed(_logger, workItem);
}

Проверьте журнальные сообщения в консольном выводе приложения. В следующем результате показано упорядочение приоритетов сообщений журнала с включенным сообщением области журнала:

info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Extreme (7d153ef9-8894-4282-836a-8e5e38319fb3): 'Verify communications'

Устаревший подход: LoggerMessage.Define (для .NET Framework и .NET Core 3.1)

Прежде чем в .NET 6 было введено логирование сгенерированного кода, рекомендовалось использовать рекомендуемый высокопроизводительный метод LoggerMessage.Define для создания кэшируемых делегатов. Хотя этот подход по-прежнему поддерживается для обратной совместимости, новый код должен использовать журналирование, генерируемое на основе исходного кода, с LoggerMessageAttribute вместо этого.

Класс LoggerMessage предоставляет функциональные возможности для создания кэшируемых делегатов, требующих меньшего количества выделений объектов и снижения вычислительных затрат по сравнению с методами расширения средства ведения журнала, такими как LogInformation и LogDebug. LoggerMessage предоставляет следующие преимущества производительности по сравнению с методами расширения логгера.

• Методы расширения для средства ведения журнала требуют "упаковку-преобразование" типов значений, таких как int, в object. Шаблон LoggerMessage избегает бокса с помощью статических Action полей и методов расширения с строго типизированными параметрами.
• Методы расширения для средства ведения журнала должны анализировать шаблон сообщения (именованную строку формата) при каждой записи сообщения журнала. LoggerMessage требует анализировать шаблон всего один раз — при определении сообщения.

Замечание

Если вы поддерживаете код, который используется LoggerMessage.Define, рассмотрите возможность миграции на генерацию ведения журнала с использованием исходного кода. Для приложений .NET Framework или .NET Core 3.1 продолжайте использовать LoggerMessage.Define.

Определите сообщение логгера

Используйте Define(LogLevel, EventId, String) для создания делегата Action для ведения журнала сообщения. Define перегрузки позволяют передавать до шести параметров типа в именованную форматированную строку (шаблон).

Строка, предоставленная Define методу, является шаблоном, а не интерполированной строкой. Заполнители заполняются в том порядке, в котором указаны типы. Имена заполнителей в шаблоне должны быть описательными и согласованными во всех шаблонах. Они служат именами свойств в структурированных данных журнала. Рекомендуется использовать стиль Pascal для имен заполнителей. Например, {Item}, {DateTime}.

Каждое Action сообщение журнала содержится в статическом поле, созданном LogerMessage.Define. Например, пример приложения создает поле для описания сообщения журнала для обработки рабочих элементов:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Для параметра Actionукажите:

• уровень ведения журнала;
• Уникальный идентификатор события (EventId) с именем метода статического расширения.
• Шаблон сообщения (именованная строка формата).

Когда рабочие элементы вынимаются из очереди для обработки, приложение службы рабочей очереди задает:

• Уровень журнала установлен на LogLevel.Critical.
• Идентификатор события 13 с именем метода FailedToProcessWorkItem.
• Преобразование шаблона сообщения (именованной форматированной строки) в строку.

s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

Метод LoggerMessage.Define используется для настройки и определения делегата Action , представляющего сообщение журнала.

Структурированные хранилища журналов могут использовать имя события вместе с идентификатором события для обогащения журналирования. Например, Serilog использует имя события.

Action вызывается через строго типизированный метод расширения. Метод PriorityItemProcessed регистрирует сообщение при каждом обработке рабочего элемента. FailedToProcessWorkItem вызывается, если и когда возникает исключение:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

Проверьте выходные данные консоли приложения:

crit: WorkerServiceOptions.Example.Worker[13]
      Epic failure processing item!
      System.Exception: Failed to verify communications.
         at WorkerServiceOptions.Example.Worker.ExecuteAsync(CancellationToken stoppingToken) in
         ..\Worker.cs:line 27

Чтобы передать параметры в сообщение журнала, определите до шести типов при создании статического поля. Пример приложения записывает сведения о рабочем элементе при обработке элементов, определяя WorkItem тип для Action поля:

private static readonly Action<ILogger, WorkItem, Exception> s_processingPriorityItem;

Шаблон сообщения журнала делегата получает значения заполнителей из указанных типов. Пример приложения определяет делегат для добавления рабочего элемента, в котором параметр элемента является WorkItem:

s_processingPriorityItem = LoggerMessage.Define<WorkItem>(
    LogLevel.Information,
    new EventId(1, nameof(PriorityItemProcessed)),
    "Processing priority item: {Item}");

Метод статического расширения для ведения журнала обработки рабочего элемента, PriorityItemProcessedполучает значение аргумента рабочего элемента и передает его делегату Action :

public static void PriorityItemProcessed(
    this ILogger logger, WorkItem workItem) =>
    s_processingPriorityItem(logger, workItem, default!);

В методе ExecuteAsync рабочей службы PriorityItemProcessed вызывается для записи сообщения:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

Проверьте выходные данные консоли приложения:

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

Оптимизации, защищённые уровнем журналирования

Вы можете оптимизировать производительность, проверив LogLevelILogger.IsEnabled(LogLevel) перед вызовом соответствующего метода Log*. Если ведение журнала не настроено для заданного LogLevel, ILogger.Log не вызывается. Кроме того, следует избегать поля типа значений и выделения object[] (для представления параметров).

Дополнительные сведения можно найти здесь

• Микро-тесты в среде выполнения .NET
• Фоновая информация и мотивация для проверок уровня логов

См. также

• Логирование в .NET
• Создание источника ведения журнала во время компиляции