Ведение журнала с высокой производительностью в .NET

Статья
04/11/2024

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

LoggerMessage предоставляет следующие преимущества производительности по сравнению с методами расширения средства ведения журнала.

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

Внимание

Вместо использования класса LogerMessage для создания журналов высокой производительности можно использовать атрибут LogerMessage в .NET 6 и более поздних версиях. Предоставляет LoggerMessageAttribute поддержку ведения журнала создания источников, предназначенную для обеспечения высокопроизводительного и высокопроизводительного решения для ведения журналов для современных приложений .NET. Дополнительные сведения см. в разделе "Создание источника ведения журнала во время компиляции" (Основы .NET).

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

Совет

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

Определение сообщения средства ведения журнала

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

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

Каждое сообщение журнала является Action, хранящимся в статическом поле, созданном LoggerMessage.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'

Определение области сообщения средства ведения журнала

Метод DefineScope(String) создает делегат Func<TResult> для определения области журнала. Перегрузки DefineScope позволяют передать до шести параметров типа в именованную строку формата (шаблон).

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

Определите область журнала, чтобы применить последовательность сообщений журнала с помощью метода DefineScope. Включите IncludeScopes в раздел средства ведения журнала консоли в файле appsettings.json:

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

Для создания области журнала добавьте поле, содержащее делегат Func<TResult> для области. Пример приложения создает поле с именем s_processingWorkScope (Internal/LoggerExtensions.cs):

private static readonly Func<ILogger, DateTime, IDisposable?> s_processingWorkScope;

Используйте DefineScope для создания делегата. При вызове делегата можно указать до шести типов для использования в качестве аргументов шаблона. Этот пример приложения использует шаблон сообщения, который содержит дату и время начала обработки.

s_processingWorkScope =
    LoggerMessage.DefineScope<DateTime>(
        "Processing scope, started at: {DateTime}");

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

public static IDisposable? ProcessingWorkScope(
    this ILogger logger, DateTime time) =>
    s_processingWorkScope(logger, time);

Область создает оболочку для вызовов расширения ведения журнала в блоке using.

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 scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Extreme (7d153ef9-8894-4282-836a-8e5e38319fb3): 'Verify communications'
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\source\repos\dotnet-docs\docs\core\extensions\snippets\logging\worker-service-options
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-High (dbad6558-60cd-4eb1-8531-231e90081f62): 'Validate collection'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1eabe213-dc64-4e3a-9920-f67fe1dfb0f6): 'Propagate selections'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1142688d-d4dc-4f78-95c5-04ec01cbfac7): 'Enter pooling [contention]'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Low (e85e0c4d-0840-476e-b8b0-22505c08e913): 'Health check network'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (07571363-d559-4e72-bc33-cd8398348786): 'Ping weather service'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (2bf74f2f-0198-4831-8138-03368e60bd6b): 'Set process state'
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...

Оптимизация с защитой на уровне журнала

Еще одну оптимизацию производительности можно выполнить, проверка при LogLevel ILogger.IsEnabled(LogLevel) этом перед вызовом соответствующего Log* метода. Если ведение журнала не настроено для заданного значения LogLevel, выполняются следующие инструкции:

ILogger.Log не вызывается.
Избегается выделение object[], представляющего параметры.
Избегается упаковка типа значения.

Дополнительные сведения см. по ссылке .

См. также

Ведение журнала в .NET

Поделиться через

Ведение журнала с высокой производительностью в .NET

Определение сообщения средства ведения журнала

Определение области сообщения средства ведения журнала

Оптимизация с защитой на уровне журнала

См. также

Дополнительные ресурсы