Часть 1: Почему стандартное логирование может тормозить .NET-приложения

Логирование — один из ключевых инструментов для мониторинга и отладки .NET-приложений. Однако стандартные подходы к сбору и хранению логов могут незаметно снижать производительность системы. Избыточные записи в логах, блокирующие операции ввода-вывода, и неоптимальная работа с хранилищем данных — всё это может привести к задержкам и росту потребления ресурсов. В первой части нашей статьи разберём, какие проблемы могут возникнуть при стандартном логировании в .NET и почему бездумное использование логов способно замедлить работу приложения.

Зачем нужно логирование

Когда приложение уже в проде, а в нем что-то сломалось, подключиться отладчиком и просто пройтись по коду, чтобы разобраться в ошибке, не выйдет. В этом случае на помощь может прийти логирование — запись событий в журнал. Таким журналом могут быть:

• консоль, 
• обычный текстовый файл, 
• системный журнал операционной системы, 
• реляционная база данных,
• специализированные средства, такие как Elastic. 

В .NET есть встроенная поддержка логирования, доступная в пространстве имен Microsoft.Extensions.Logging. О том, как инициализировать логирование, можно почитать в документации. Скажем лишь, что в результате мы можем получить экземпляр ILogger — он предоставляет расширения, которые позволяют записывать события с различным уровнем серьезности (severity). Severity — атрибут, который определяет, насколько сильно дефект может повлиять на работу.

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

• Методы расширения ILogger выполняют упаковку (boxing) значимых типов для преобразования их в object. Это верно для bool, int и др.;
• Методы расширения ILogger выполняют разбор (parsing) шаблона сообщения каждый раз, когда вызывается соответствующий метод расширения.

Как работает высокопроизводительное логирование

Microsoft предлагает другой механизм записи сообщений в журнал — с помощью LoggerMessage. Этот класс позволяет избежать следующих проблем:

• Проблема упаковки (boxing). Решается за счет перегруженных методов с обобщенными параметрами.
• Проблема разбора шаблона сообщения. Решается так: разбор производится один раз в момент объявления специфического метода для записи сообщения.

Ниже покажем, как использовать LoggerMessage в приложении, и сравним его производительность с методами расширения ILogger из LoggerExtensions и типизированными методами из LoggerMessageExtensions.

Для начала создадим новый проект типа Console Application. Будем использовать фреймворк .Net9.

После создания проекта нам нужно подключить следующие nuget-пакеты:

			Microsoft.Extensions.Logging.Abstractions
Microsoft.Extensions.Logging
Microsoft.Extensions.Logging.Console
		

Далее инстанцируем в приложении экземпляр ILogger:

			using Microsoft.Extensions.Logging;
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
ILogger logger = loggerFactory.CreateLogger();
		

При использовании LoggerMessage для каждого типа события нам нужно создать отдельный метод логирования. Для начала — написать статический класс, который будет выступать хранилищем (реестром сообщений). Добавим LoggerExtensions:

			using Microsoft.Extensions.Logging;
namespace AutoLoggingNet9;
internal static class LoggerExtensions
{
    static LoggerExtensions() { }
}
		

Добавим метод для логирования старта приложения, сохраняя имя хоста. Метод должен соответствовать следующему делегату:

			Action(LogLevel logLevel, EventId eventId, string formatString)
		

Где:

• T1..T6 —  обобщенные типы параметров, которые мы можем передать во время записи сообщения в журнал;
• logLevel — уровень логирования (степень серьезности) события;
• eventid — уникальный идентификатор события;
• formatString — шаблон сообщения.

В классе LoggerExtensions для каждого лог-сообщения объявляем Action-делегат в приватном статическом поле. Экземпляр этого делегата инициализируем через LoggerMessage.Define в конструкторе — для его вызова нужно определить public-метод. Код для метода LogApplicationStart:

			internal static class LoggerExtensions
{
    private static readonly Action s_applicationStart;
    static LoggerExtensions()
    {
        s_applicationStart = LoggerMessage.Define(
            LogLevel.Information,
            new EventId(0, nameof(LogApplicationStart)),
            "Application started on host '{HostName}'"
        );
    }
    /// <summary>
    /// Записывает событие "Старт приложения"
    /// </summary>
    /// <param name="logger">Экземпляр <see cref="ILogger" /></param>
    /// <param name="hostName">Имя хоста, где запущено приложение</param>
    public static void LogApplicationStart(this ILogger logger, string hostName) =>
        s_applicationStart(logger, hostName, null);
}
		

Как работает LoggerMessage.Define T

Давайте разберемся немного глубже и посмотрим, что же делает метод Define. Код метода для одного обобщенного параметра приведен ниже:

			public static Action Define(LogLevel logLevel, EventId eventId, string formatString, LogDefineOptions? options)
{
    LogValuesFormatter formatter = CreateLogValuesFormatter(formatString, expectedNamedParameterCount: 1);

    void Log(ILogger logger, T1 arg1, Exception? exception)
    {
        logger.Log(logLevel, eventId, new LogValues(formatter, arg1), exception, LogValues.Callback);
    }
 
    if (options != null && options.SkipEnabledCheck)
    {
        return Log;
    }
 
    return (logger, arg1, exception) =>
    {
        if (logger.IsEnabled(logLevel))
        {
            Log(logger, arg1, exception);
        }
    };
}
		

В первой строке метод CreateLogValuesFormatter разбирает шаблон сообщения и проверяет соответствие количества плейсхолдеров числу обобщённых параметров Define. Если не совпадает — возбуждается исключение.

Локальная функция Log вызывает ILogger.Log и записывает сообщение в журнал.

Ниже идет проверка флага SkipEnabledCheck:

• Если true, сообщение записывается без учёта объявленного уровня логирования.
• Если false (или options не предоставлен), сначала проверяется уровень логирования. Если наше событие объявлено с уровнем, подлежащим записи, то будет произведен вызов функции Log.

Выводы:

1. Результат метода, делегат Action, мы сохраняем в приватном статическом поле. То есть Define выполнится лишь один раз за время жизни приложения. То же самое и с разбором шаблона каждого сообщения.
2. Делегат проверяет уровень логирования, исключая ненужные вызовы ILogger.Log — это повышает производительность.
3. Наличие параметров Define и делегатов Action позволяет избежать упаковки значимых типов — это снижает нагрузку на память и процессор.

Добавим вызов этого метода в наше приложение:

			using AutoLoggingNet9;
using Microsoft.Extensions.Logging;
using System.Net;
 
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
 
ILogger logger = loggerFactory.CreateLogger();
 
logger.LogApplicationStart(Dns.GetHostName());
		

Если запустить, то в консоли мы увидим такой вывод:

Добавим сообщение, которые говорит об окончании работы приложения. В качестве параметра выводим в лог время выполнения. Вот основные изменения в LoggerExtensions:

			using Microsoft.Extensions.Logging;

namespace AutoLoggingNet9;

internal static partial class LoggerExtensions
{
    /// <summary>
    /// Записывает событие "Старт приложения".
    /// </summary>
    /// <param name="logger">Экземпляр <see cref="ILogger" /></param>
    /// <param name="hostName">Имя хоста, где запущено приложение</param>
    [LoggerMessage(EventId = 0, EventName = nameof(LogApplicationStart), Level = LogLevel.Information, Message = "Application started on host '{HostName}'")]
    public static partial void LogApplicationStart(this ILogger logger, string hostName);

    /// <summary>
    /// Записывает событие "Приложение завершено" с указанием времени, потребовавшегося на выполнение приложения.
    /// </summary>
    /// <param name="logger">Экземпляр <see cref="ILogger" /></param>
    /// <param name="elapsed">Время, затраченное на выполнение приложения</param>
    [LoggerMessage(EventId = 1000, EventName = nameof(LogApplicationFinish), Level = LogLevel.Information, Message = "Application is done. ElapsedTime: {Elapsed:g}")]
    public static partial void LogApplicationFinish(this ILogger logger, TimeSpan elapsed);
}

		

Выше добавили еще одно приватное поле, public-метод и код инициализации делегата.

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

			using AutoLoggingNet9;
using Microsoft.Extensions.Logging;
using System.Diagnostics;
using System.Net;
 
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
 
ILogger logger = loggerFactory.CreateLogger();
 
logger.LogApplicationStart(Dns.GetHostName());
 
var sw = Stopwatch.StartNew();
try
{
    // Имитация выполнения работы приложения
    Thread.Sleep(2000);
}
finally
{
    sw.Stop();
    logger.LogApplicationFinish(sw.Elapsed);
		

Вывод будет такой:

Резюмируем, что нужно сделать с LoggerMessage для каждого события:

• Добавить в статический класс приватное поле для сохранения ссылки на делегат. 
• Определить публичный метод расширения. 
• Добавить инициализацию делегата в конструктор статического класса.

Это кажется сложнее, чем обычные методы ILogger. К счастью, есть LoggerMessageAttribute, который позволяет уменьшить объем работы.

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

С LoggerMessageAttribute, для объявления метода расширения, нужно сделать следующее:

• Пометить класс с методами расширения директивой partial — объявить класс частичным;
• Объявить публичный метод расширения — тоже частичный;
• Декорировать этот метод атрибутом LoggerMessageAttribute.

Это приведет к тому, что во время компиляции сработает механизм перехватчика, который сгенерирует весь необходимый код за нас. Вот обновленный код класса LoggerExtensions:

			using Microsoft.Extensions.Logging;
 
namespace AutoLoggingNet9;
 
internal static partial class LoggerExtensions
{
    /// 
    /// Записывает событие "Старт приложения".
    /// 
    /// Экземпляр 
    /// Имя хоста, где запущено приложение
    [LoggerMessage(EventId = 0, EventName = nameof(LogApplicationStart), Level = LogLevel.Information, Message = "Application started on host '{HostName}'")]
    public static partial void LogApplicationStart(this ILogger logger, string hostName);
 
    /// 
    /// Записывает событие "Приложение завершено" с указанием времени, потребовавшегося на выполнение приложения.
    /// 
    /// Экземпляр 
    /// Время, затраченное на выполнение приложения
    [LoggerMessage(EventId = 1000, EventName = nameof(LogApplicationFinish), Level = LogLevel.Information, Message = "Application is done. ElapsedTime: {Elapsed:g}")]
    public static partial void LogApplicationFinish(this ILogger logger, TimeSpan elapsed);
		

До момента компиляции Visual Studio будет показывать, что в коде есть ошибки — нужно дописать тела объявленных методов. Не пугайтесь: просто выполните сборку проекта и ошибки уйдут.

Что же делает этот атрибут? Давайте посмотрим на сгенерированный код:

			[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "9.0.11.11010")]
private static readonly global::System.Action __LogApplicationFinishCallback =
    global::Microsoft.Extensions.Logging.LoggerMessage.Define(global::Microsoft.Extensions.Logging.LogLevel.Information, newglobal::Microsoft.Extensions.Logging.EventId(1000, "LogApplicationFinish"), "Application is done. ElapsedTime: {Elapsed:g}", newglobal::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true }); 
 
[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "9.0.11.11010")]
public static partial void LogApplicationFinish(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.TimeSpan elapsed)
{
    if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Information))
    {
        __LogApplicationFinishCallback(logger, elapsed, null);
    }
}
		

Для каждого частичного метода будет сгенерировано:

• Приватное поле для хранения ссылки на делегат. Имя поля начинается с двойного символа underscore(_), в этом случае  называется __LogApplicationFinishCallback,
• Код инициализации делегата,
• Тело метода расширения.

Метод проверяет уровень логирования: если событие уровня Debug, а минимальный уровень — Information, делегат не вызывается. Это улучшает производительность. А LoggerMessageAttribute упрощает создание методов расширения, снижая трудозатраты.

В следующей статье мы сравним производительность стандартного логирования и LoggerMessage на реальных примерах, а также покажем, как легко оптимизировать код с помощью AutoLoggerMessage. Не переключайтесь!

А если хотите больше узнать про .NET, сразу переходите в наш Telegram канал, это точно ускорит время ожидания!