CA2254, логирование в C# и проблемы с производительностью

Что такое CA2254?

CA2254 — это предупреждение анализатора для Microsoft.Extensions.Logging. Текст предупреждния следующий:

The logging message template should not vary between calls.

Проще говоря, текст шаблона не должен изменяться.

// Плохо
logger.LogDebug($"Request Id: {Id} finished with Error: {Error}");

// Лучше
logger.LogDebug("Request Id: {Id} finished with Error: {Error}", Id, Error);

Почему так логировать не надо?

Потому что интерполированные строки — это синтаксический сахар. После компиляции код будет выглядеть так:

// До компиляции
logger.LogDebug($"Request Id: {id} finished with Error: {error}");

// После компиляции
var handler = new DefaultInterpolatedStringHandler(34, 2);
handler.AppendLiteral("Request Id: ");
handler.AppendFormatted(value);
handler.AppendLiteral(" finished with Error: ");
handler.AppendFormatted(value2);
string text = handler.ToStringAndClear();
logger.LogDebug(text);

Проблема здесь в том, что строка text создаётся всегда, даже если уровень логирования выше Debug и сообщение в лог не попадёт. Это приводит к лишним аллокациям и ухудшает производительность.

Помогут ли строковые шаблоны?

Более правильный вариант логирования выглядит так:

logger.LogDebug("Request Id: {Id} finished with Error: {Error}", Id, Error);

В этом случае строковый шаблон Request Id: {Id} finished with Error: {Error} не будет использоваться, если, например, минимальный уровень логирования Information.

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

Каково влияние на производительность?

Если сделать профилирование памяти, видно, что в обоих случаях размер Gen0 растёт. При использовании шаблонов память выделяется действительно меньше (3.09 МБ против 8.22 МБ), но аллокации всё равно происходят.

И это происходит даже если текущий уровень логирования — Information, а вызывается LogDebug.

Причин этому несколько.

Причины скрытых аллокаций

Причина 1 — Использование params object[]

Методы расширения из LoggerExtensions принимают params object[]. Поэтому, на каждый вызов методов логирования будет создан новый массив.

// Исходный код
logger.LogDebug("Integers: {i1}, {i2}, {i3}", 1, 2, 3);

// Код после компиляции
object[] array = new object[3];
array[0] = 1;
array[1] = 2;
array[2] = 3;
logger.LogDebug("Integers: {i1}, {i2}, {i3}", array);

Если логируются значимые типы (int, bool, struct), происходит упаковка (boxing), что приводит к дополнительным аллокациям.

Причина 2 — Скрытые аллокации в классе Logger

Методы LogDebug, LogInformation, LogError и другие, внутри вызывают метод Log, в котором создаётся структура FormattedLogValues:

public static void Log(this ILogger logger, LogLevel logLevel, EventId eventId, Exception? exception, string? message, params object?[] args)
{
    ArgumentNullException.ThrowIfNull(logger);

    logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);
}

Внутри FormattedLogValues есть ConcurrentDictionary, использование которого тоже приводит к аллокациям.

Конструктор FormattedLogValues:

public FormattedLogValues(string? format, params object?[]? values)
{
    if (values != null && values.Length != 0 && format != null)
    {
        if (s_count >= MaxCachedFormatters)
        {
            if (!s_formatters.TryGetValue(format, out _formatter))
            {
                // Аллокация
                _formatter = new LogValuesFormatter(format);
            }
        }
        else
        {
            // Аллокация
            _formatter = s_formatters.GetOrAdd(format, f =>
            {
                Interlocked.Increment(ref s_count);
                return new LogValuesFormatter(f);
            });
        }
    }
    else
    {
        _formatter = null;
    }

    _originalMessage = format ?? NullFormat;
    _values = values;
}

Причина 3 — Уровень логирования проверяется не сразу

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

– создать FormattedLogValues;
– проверить наличие кэшированного шаблона в словаре;
– выполнить другие вспомогательные действия.

Только после этого будет решено, писать ли что-то в лог.

Решение — LoggerMessageAttribute

Начиная с .NET 6 в C# есть атрибут LoggerMessageAttribute, который лишён недостатков, перечисленных ранее.

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

[LoggerMessage(Level = LogLevel.Debug, Message = "Integers: {i1}, {i2}")]
public static partial void LogIntegers(ILogger logger, int i1, int i2);

Компилятор сгенерирует типизированный делегат, отвечающий за логирование и тело метода LogIntegers.

private static readonly Action<ILogger, int, int, Exception?> __LogIntegers1Callback =
    LoggerMessage.Define<int, int>(
    LogLevel.Debug,
    new EventId(666252842, nameof(LogIntegers)),
    "Integers: {i1}, {i2}",
    new LogDefineOptions() { SkipEnabledCheck = true });

public static partial void LogIntegers(ILogger logger, int i1, int i2)
{
    if (logger.IsEnabled(LogLevel.Debug))
    {
        __LogIntegers1Callback(logger, i1, i2, null);
    }
}

Основные отличия следующие:

1. Сразу проверяется уровень логирования.
2. Сигнатура метода и типы делегата в точности повторяют передаваемые аргументы.

Всё это позволяет улучшить производительность. Вместо прежних аллокаций мы получаем всего 1.36 МБ памяти в Gen0, и это значение стабильно.

Выводы

• Интерполяция строк в логировании приводит к лишним аллокациям даже при выключенных уровнях логирования.
• Использование шаблонов снижает количество аллокаций, но полностью их не устраняет.
• Причины скрытых аллокаций: создание массива params object[], упаковка значимых типов, создание FormattedLogValues и обращение к словарю.
• Самый эффективный способ логировать с точки зрения производительности - Использовать LoggerMessage, доступный начиная с .NET 6: он минимизирует аллокации за счёт генерации кода.

Если важна производительность и особенно если логирование в «горячих» местах кода — используйте атрибут LoggerMessage.