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


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

Класс 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 методу, является шаблоном, а не интерполированной строкой. Заполнители заполняются в том порядке, в который указаны типы. Имена заполнителей в шаблоне должны быть описательными и согласованными во всех шаблонах. Они служат именами свойств в структурированных данных журнала. Мы рекомендуем использовать ПаскальКейс для имен заполнителей. Например, {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'

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

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

Как и в случае с Define методом, строка, предоставленная DefineScope методу, является шаблоном, а не интерполированной строкой. Заполнители заполняются в том порядке, в который указаны типы. Имена заполнителей в шаблоне должны быть описательными и согласованными во всех шаблонах. Они служат именами свойств в структурированных данных журнала. Мы рекомендуем использовать ПаскальКейс для имен заполнителей. Например, {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);

Область упаковывает вызовы расширения ведения журнала в блок с помощью :

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[], представляющего параметры.
  • Поле типа значений избегается.

Дополнительные сведения:

См. также