Часть 2: Как оптимизировать логирование в .NET: советы и примеры

Это продолжение нашей серии о логировании в .NET. В первой части мы разобрали, как стандартные методы могут замедлять приложение, и познакомились с LoggerMessage. Теперь пора перейти к практике: мы покажем реальные тесты производительности и расскажем, как автоматизировать переход на эффективное логирование.

Сравнение производительности: стандартное логирование против LoggerMessage

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

			[LoggerMessage(EventId = 10, EventName = nameof(LogIterationStart), Level = LogLevel.Information, Message = "Iteration start [{Iteration}]")]
public static partial void LogIterationStart(this ILogger logger, int iteration);
 
[LoggerMessage(EventId = 20, EventName = nameof(LogIterationComplete), Level = LogLevel.Information, Message = "Iteration complete [{Iteration}] Current summ: [{Summ}]")]
public static partial void LogIterationComplete(this ILogger logger, int iteration, int summ);
 
[LoggerMessage(EventId=30, EventName =nameof(LogOddItem), Level = LogLevel.Information, Message = "Iteration [{Iteration}] An odd item detected: [{OddItem}]")]
public static partial void LogOddItem(this ILogger logger, int iteration, int oddItem);
 
[LoggerMessage(EventId = 999, EventName = nameof(LogException), Level = LogLevel.Error, Message = "An unexpected exception has occurred")]
public static partial void LogException(this ILogger logger, Exception exception);
		

Обновленный код приложения:

			using AutoLoggingNet9;
using Microsoft.Extensions.Logging;
using System.Diagnostics;
using System.Net;
 
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
 
ILogger logger = loggerFactory.CreateLogger<Program>();
 
logger.LogApplicationStart(Dns.GetHostName());
 
var sw = Stopwatch.StartNew();
try
{
    // Имитация выполнения работы приложения
    const int N = 100000;
    var random = new Random();
    var numbers = Enumerable.Range(0, N).Select(x => random.Next(N / 100)).ToArray();
    var summ = 0;
    for (int i = 0; i < N; i++)
    {
        logger.LogIterationStart(i);
        //logger.LogInformation("Iteration start [{Iteration}]", i);
 
        if (numbers[i] % 2 == 0) // четный элемент
        {
            if ((long)summ + numbers[i] >= int.MaxValue)
            {
                throw new InvalidOperationException("The uint.MaxValue is exceeded!");
            }
 
            summ += numbers[i];
        }
        else // нечетный элемент
        {
            logger.LogOddItem(i, numbers[i]);
            //logger.LogInformation("Iteration [{Iteration}] An odd item detected: [{OddItem}]", i, numbers[i]);
        }
 
        logger.LogIterationComplete(i, summ);
        //logger.LogInformation("Iteration complete [{Iteration}] Current summ: [{Summ}]", i, summ);
    }
}
catch (Exception ex)
{
    logger.LogException(ex);
    //logger.LogError(ex, "An unexpected exception has occurred");
}
finally
{
    sw.Stop();
    logger.LogApplicationFinish(sw.Elapsed);
}

		

Здесь строки вызова методов расширения ILogger закомментированы. А вызовы наших методов, построенных через механизм LoggerMessage, раскомментированы. Таким образом, можно прогнать программу, используя ILogger, либо, наоборот, LoggerMessage

При использовании механизма LoggerMessage затраты на выполнение методов логирования, которые мы вызывали в цикле (LogIterationStart и LogIterationComplete), составили 0,58% и 0,52% процессорного времени от общих затрат.

При использовании методов расширения ILogger затраты на выполнение метода ILogger.LogInformation составили 35,12% от общих затрат.

Да, можно заметить, что в затраты попали вызовы метода LoggerMessage.Define. Но заметим, что эти методы выполняются один раз на старте приложения. И если наше приложение серверное (долгоживущее), то затраты станут ничтожными по отношению к общим затратам за всё время жизни приложения.

При использовании же методов расширения ILogger затраты на выполнение будут расти, создавая нагрузку как на процессор, так и на память.

AutoLoggerMessage: как легко перейти на высокопроизводительное логирование

Мы рассмотрели два способа типизированных методов для ILogger. LoggerMessageAttribute упрощает процесс, но перевод готового проекта всё равно сложный.

К счастью, есть nuget-пакет, который умеет преобразовывать методы расширения ILogger.Log* из пространства имен Microsoft.Extensions.Logging в строго типизированные методы LoggerMessage.

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

Добавить в проект nuget-пакет stbychkov.AutoLoggerMessage

Это можно сделать либо через консоль с помощью инструмента Nuget package Manager, либо добавив ссылку на пакет в файл проекта.

Команда консоли Nuget Package Manager:

Install-Package stbychkov.AutoLoggerMessage

Добавление пакета с помощью утилиты dotnet:

dotnet add package stbychkov.AutoLoggerMessage

Разрешить перехватчики для генерации исходного кода

			<PropertyGroup>
   <InterceptorsPreviewNamespaces>$(InterceptorsPreviewNamespaces);
Microsoft.Extensions.Logging.AutoLoggerMessage</InterceptorsPreviewNamespaces>
</PropertyGroup>

		

Для тестирования этого пакета мы создали отдельный проект консольного приложения и подключили в него указанный nuget-пакет. Далее добавили в модуль Program.cs пару строк с вызовами ILogger.LogInformation:

			using Microsoft.Extensions.Logging;
using System.Diagnostics;
 
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
 
ILogger logger = loggerFactory.CreateLogger<Program>();
 
logger.LogInformation("Hello, World");
 
var sw = Stopwatch.StartNew();
try
{
 
}
finally
{
    sw.Stop();
    logger.LogInformation("Application is done.Elapsed time: {Elapsed:g}", sw.Elapsed);
		

Если попытаться перейти к реализации метода LogInformation с помощью команды Go To Implementation, мы увидим, что попали не в метод расширения класса LoggerExtensions, а в строго типизированный метод в классе GenericLoggerExtensions:

Для первого вызова, где передана только строка сообщения, будет вызван этот метод:

			[GeneratedCode("AutoLoggerMessageGenerator", "1.0.0.0")]
[EditorBrowsable(EditorBrowsableState.Never)]
[DebuggerStepThrough]
[ExcludeFromCodeCoverage]
public static class GenericLoggerExtensions
{
    . . .
    public static void LogInformation(this ILogger logger, string message)
    {
        LoggerExtensions.LogInformation(logger, message);
    }
    . . .
}

		

Для второго вызова, где передан параметр типа TimeSpan, будет вызван следующий метод:

			public static void LogInformation<T0>(this ILogger logger, string message, T0 arg0)
{
    LoggerExtensions.LogInformation(logger, message, arg0);
}

		

Как видите, второй метод имеет обобщенный параметр.

			public static void LogInformation(this ILogger logger, string? message, params object?[] args)
{
    logger.Log(LogLevel.Information, message, args);
}

		

Можно заметить, что внутри есть вызовы LoggerExtensions, которые не строго типизированы. Это нужно, поскольку во время компиляции вложенный вызов logger.Log должен быть заменен сгенерированным кодом, который в итоге будет вызывать подходящий строго типизированный метод расширения класса LoggerMessageExtensions.

Сборка проекта как в MS Visual Studio 2022, так и в JetBrains Rider, прошла без проблем. Так, если в IDE Rider запустить отладку проекта, предварительно поставив точку останова на вызове одного из методов logger.LogInformation(), то можно увидеть код, который будет вызван. Для этого выберите команду Step Into:

Мы можем видеть, что дальше управление передается сгенерированному методу с типизированными параметрами:

Этот код построен на LoggerMessage.Define – следующим шагом мы попадаем в один из методов расширения класса LoggerMessage:

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

Правда, у AutoLoggerMessage есть ограничения:

1. Поддерживается с .NET 8.0.8 и выше;
2. В ILogger.Log*() может быть не более 6 параметров, иначе параметры передаются как массив object, то есть вызывается упаковка значимых типов.

Какой подход к логированию выбрать

Подводя итоги, приведем плюсы и минусы каждого подхода.

ILogger и методы расширения Log*() класса LoggerExtensions

+ Если используете ILogger из коробки, вам не нужно добавлять статический класс с объявлениями методов расширения.

- Так как дополнительные параметры передаются как object, то выполняется упаковка значимых типов.

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

- Код загрязняется текстом шаблонов сообщений.

- Поскольку сообщения добавляются по мере необходимости прямо в код классов, то возможно дублирование сообщений.

LoggerMessage и строго типизированные методы класса LoggerMessageExtensions

+ Не загрязняют код шаблонами сообщений.

+ Методы расширений имеют строго типизированные параметры — это исключает упаковку значимых типов.

+ Шаблоны сообщений разбираются один раз во время старта приложения.

+ Все сообщения хранятся в одном статическом классе, которым проще управлять.

- Придется добавить статический класс и статический метод для каждого вновь добавляемого сообщения.

В целом, подход с LoggerMessage имеет больше преимуществ. А с пакетом AutoLoggerMessage можно легко перевести проекты на более производительное логирование.

Исходный код можно посмотреть на bitbucket. А узнать больше информации про .NET — в нашем канале.

Полезные ссылки

Logging in C# - .NET | Microsoft Learn

High-performance logging - .NET | Microsoft Learn

Compile-time logging source generation - .NET | Microsoft Learn

AutoLoggerMessage