Структурное логирование и интерполированные строки в C# 10

В последние годы все большую популярность у разработчиков завоевывает структурное логирование. Поэтому неудивительно, что Microsoft добавило его поддержку в пакет Microsoft.Extensions.Logging, являющийся составляющей частью .Net Core/.Net 5/.Net 6. В этой статье я хотел бы рассмотреть, как мы можем использовать структурное логирование с данным пакетом и показать идею, как мы можем расширить его с использованием новых возможностей C# 10.

Первоначальная настройка

Как известно, Microsoft.Extensions.Logging представляет собой фасад, к которому мы можем подключать различные нижележащие провайдеры логирования. В данной статье я буду использовать Serilog в качестве такого провайдера и настрою его для вывода логов на консоль в формате JSON.

В качестве примера мы будем рассматривать простое консольное приложение (ссылка на GitHub), в котором конфигурация логирования имеет следующий вид:

// Конфигурируем Serilog
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .WriteTo.Console(new CompactJsonFormatter())
    .CreateLogger();   

// Регистрируем Serilog при создании Microsoft.Extensions.Logging.LoggerFactory
using var loggerFactory = LoggerFactory.Create(
    builder => builder.AddSerilog(dispose: true));
// Создаем экземпляр ILogger при помощи фабрики
var logger = loggerFactory.CreateLogger<Program>();

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

public record Point(double X, double Y);

public record Segment(Point Start, Point End)
{
    public double GetLength()
    {
      var dx = Start.X - End.X;
      var dy = Start.Y - End.Y;
      return Math.Sqrt(dx * dx + dy * dy);
    }
}

Использование ILogger

Для логирования мы будем использовать интерфейс ILogger, который предоставляет несколько перегрузок метода Log, позволяющего указать уровень логирования в качестве параметра, а также методов вида Log<уровень>, например LogInformation, LogError и т.п. Все эти методы принимают в качестве параметров строку шаблона и массив аргументов (params object[]).

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

var segment = new Segment(new (1, 2), new (4, 6));
var length = segment.GetLength();
logger.LogInformation(
    "The length of segment {@segment} is {length}.", segment, length);

Строка формата имеет два аргумента, заключенных в фигурные скобки: segment и length. Значения аргументов передаются как последующие параметры метода. Символ @ перед аргументом segment является частью соглашения Message Template и означает, что Serilog должен развернуть структуру аргумента как объект. Без данного символа Serilog по умолчанию просто залогировал бы результат вызова метода segment.ToString().

В результате мы получим в логе следующую запись:

{
	"@t": "2021-11-13T19:57:31.8636016Z",
	"@mt": "The length of segment {@segment} is {length}.",
	"segment": {
		"Start": {
			"X": 1,
			"Y": 2,
			"$type": "Point"
		},
		"End": {
			"X": 4,
			"Y": 6,
			"$type": "Point"
		},
		"$type": "Segment"
	},
	"length": 5,
	"SourceContext": "Program"
}

Получившийся JSON-объект имеет свойство @mt, содержащее нашу строку шаблона, а также свойства segment и length, содержащие наши аргументы.

Несмотря на то, что данный подход достаточно прост и прямолинеен, он имеет ряд существенных недостатков:

• Необходимость разбирать строку формата во время выполнения, что является достаточно затратным. Чтобы сгладить этот недостаток, инфраструктура логирования имеет кэш на 1024 строки.

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

• Аргументы значимых типов упаковываются при помещении в массив объектов.

• Дублирование имен переменных в строке шаблона и в параметрах метода.

• Легко забыть один из параметров или перепутать их порядок.

В качестве альтернативы, лишенной всех этих недостатков, .Net 6 предлагает использовать новый генератор исходного кода: мы можем объявить частичный (partial) метод, принимающий нужные нам параметры и пометить его атрибутом LoggerMessageAttribute, как показано в следующем примере:

[LoggerMessage(0, LogLevel.Information, "The length of segment {segment} is {length}.")]
public static partial void LogSegmentLength(this ILogger logger, Segment segment, double length);

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

• Захламляет исходный код объявлениями частичных методов.

• Не позволяет использовать символ @ перед имена аргументов, из-за чего Serilog не разворачивает их значения в объекты JSON.

Добавляем поддержку интерполированных строк в ILogger

Итак, нам бы хотелось найти выразительный способ писать структурные логи и по возможности избежать описанных выше недостатков. Удобным способом могло бы стать интерполирование строк. Однако для этого нам придется сначала проделать дополнительную работу.

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

logger.LogInformation($"The length of segment {segment} is {length}.");

то в логах мы получим следующую запись:

{
	"@t": "2021-11-13T23:40:23.1323976Z",
	"@mt": "The length of segment Segment { Start = Point { X = 1, Y = 2 }, End = Point { X = 4, Y = 6 } } is 5.",
	"SourceContext": "Program"
}

Как и следовало ожидать, мы потеряли всю информацию об аргументах. Это произошло потому, что компилятор C# превратил нашу интерполированную строку в обычный вызов метода String.Format.

Вообще говоря, до C# 10, компилятор мог преобразовать интерполированную строку либо в объект типа FormattableString, либо в обычную строку. Объекты типа FormattableString уже больше похожи на то, что нам нужно для решения нашей задачи, так как содержат в себе строку форматирования и массив аргументов в неизменном виде, однако их возможностей все еще недостаточно, так как мы теряем имена аргументов. Кроме того, при выборе перегрузки метода, C# отдает предпочтение версии, принимающей строку, что также не очень удобно на практике.

К счастью, в C# 10 появился новый механизм для интерполированных строк, которые позволит нам добиться того, чего мы хотим. Вкратце, мы можем создать структуру-обработчик интерполированных строк, предназначенную специально для нашей задачи:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    // Код обработчика будет приведен ниже
}

Далее мы можем использовать ее как аргумент метода. Создадим, для примера, метод расширения Log:

public static partial class LoggerExtensions
{
    public static void Log(this ILogger logger, LogLevel logLevel, 
        [InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
    {
        // Код метода будет приведен ниже
    }
}

Если теперь мы попробуем, передать интерполированную строку в наш метод Log:

logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");

то компилятор превратит этот вызов в следующий код:

var handler = new StructuredLoggingInterpolatedStringHandler(
    27, 2, logger, LogLevel.Information, out bool isEnabled);
if (isEnabled)
{
	handler.AppendLiteral("The length of segment ");
	handler.AppendFormatted(segment);
	handler.AppendLiteral(" is ");
	handler.AppendFormatted(length);
	handler.AppendLiteral(".");
}
logger.Log(LogLevel.Information, ref handler);

Как мы видим, компилятор использует вызов метода AppendLiteral для добавления литеральной части строки и вызов метода AppendFormatted для аргументов, а значит мы можем написать наш обработчик так, чтобы он сформировал строку шаблона, которую мы сможем передать в оригинальный метод ILogger.Log, а также список аргументов.

У вас может возникнуть вопрос, а откуда мы получим имена наших аргументов. В это нам поможет еще одна новая возможность C# 10 - CallerArgumentExpressionAttribute. Как и в случае с другими родственными Caller*-атрибутами, мы можем пометить им дополнительный строковый параметр метода AppendFormatted, и компилятор вставит в качестве значения C#-выражение, использованное при вызове метода для другого параметра этого же метода.

Итак, давайте соберем все то, что мы узнали вместе и напишем код нашего обработчика.

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

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    private readonly StringBuilder _template = null!;
    private readonly List<object?> _arguments = null!;

    public bool IsEnabled { get; }
  
    // ...
}

Далее мы должны создать конструктор, принимающий длину строкового литерала, количество аргументов, экземпляр ILogger, уровень логирования для сообщения и выходной параметр IsEnabled.

public StructuredLoggingInterpolatedStringHandler(
    int literalLength, 
    int formattedCount, 
    ILogger logger, 
    LogLevel logLevel, 
    out bool isEnabled)
{
    IsEnabled = isEnabled = logger.IsEnabled(logLevel);
    if (isEnabled)
    {
        _builder = new StringBuilder(literalLength);
        _arguments = new List<object?>(formattedCount);
    }
}

Обратите внимание, что мы создаем StringBuilder и List<object?> только в случае, если переданный уровень логирования включен, тем самым экономя ресурсы, если это не так.

Также у вас мог возникнуть вопрос, откуда компилятор получает ILogger и уровень логирования. Если вы посмотрите немного выше на объявление метода Log, то увидите, что параметр обработчика помечен атрибутом [InterpolatedStringHandlerArgument("logger", "logLevel")] с двумя аргументами. Эти аргументы указывают имена параметров этого метода, которые содержат эти объекты.

Далее, добавим метод AppendLiteral:

public void AppendLiteral(string s)
{
    if (!IsEnabled) 
        return;

    _template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
}

В коде этого метода мы также экранируем фигурные скобки вызовами метода String.Replace. На самом деле мы могли бы провести экранирование в один проход, однако для простоты примера оставим этот код как есть.

Наконец, добавим метод AppendFormatted:

public void AppendFormatted<T>(
    T value, 
    [CallerArgumentExpression("value")] string name = "")
{
    if (!IsEnabled)
        return;

    _arguments.Add(value);
    _template.Append($"{{@{name}}}");
}

Как я и говорил ранее, он содержит параметр name со значением по-умолчанию и помеченный атрибутом [CallerArgumentExpression("value")]. Вместо значения по умолчанию компилятор подставит C#-выражение использованное при вызове для параметра value (в простейшем случае - имя переменной).

Обратите внимание, что я всегда добавляю символ @ перед именем аргумента. Насколько я вижу, Serilog нормально обрабатывает его в том числе для примитивных/встроенных типов. Впрочем, если бы это было не так, мы всегда могли бы сделать отдельные перегрузки метода AppendFormatted для таких типов.

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

public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());

Наш обработчик готов! Полный его код вы можете найти под спойлером:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    private readonly StringBuilder _template = null!;
    private readonly List<object?> _arguments = null!;

    public bool IsEnabled { get; }

    public StructuredLoggingInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, LogLevel logLevel, out bool isEnabled)
    {
        IsEnabled = isEnabled = logger.IsEnabled(logLevel);
        if (isEnabled)
        {
            _template = new (literalLength);
            _arguments = new (formattedCount);
        }
    }

    public void AppendLiteral(string s)
    {
        if (!IsEnabled) 
            return;

        _template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
    }

    public void AppendFormatted<T>(T value, [CallerArgumentExpression("value")] string name = "")
    {
        if (!IsEnabled)
            return;

        _arguments.Add(value);
        _template.Append($"{{@{name}}}");
    }

    public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());
}

Наш метод расширения Log может использовать его следующим образом:

public static partial class LoggerExtensions
{
    public static void Log(this ILogger logger, LogLevel logLevel, 
        [InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
    {
        if (handler.IsEnabled)
        {
            var (template, arguments) = handler.GetTemplateAndArguments();
            logger.Log(logLevel, template, arguments);
        }
    }
}

Теперь все готово, чтобы использовать его для логирования:

logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");

В результате мы получим правильное сообщение:

{
	"@t": "2021-11-14T02:13:34.8380946Z",
	"@mt": "The length of segment {@segment} is {@length}.",
	"segment": {
		"Start": {
			"X": 1,
			"Y": 2,
			"$type": "Point"
		},
		"End": {
			"X": 4,
			"Y": 6,
			"$type": "Point"
		},
		"$type": "Segment"
	},
	"length": 5,
	"SourceContext": "Program"
}

Кстати, обратите внимание на то, что перегрузка метода, принимающая обработчик, имеет приоритет над перегрузкой, принимающей строку. В данном случае, по моему мнению, разработчики C# исправили ошибку с приоритетами, которую допустили с FormattableString в C# 6.

Итак, теперь у нас есть метод расширения, позволяющий писать в лог с указанным уровнем. Нам также хотелось бы иметь методы специфичные для каждого уровня логирования, такие как LogError. Мы можем создать их по аналогии, однако наш оригинальный обработчик требует передачи уровня логирования в качестве аргумента, который отсутствует в наших методах. Чтобы решить эту проблему, нам придется создать отдельный обработчик для каждого уровня логирования. К счастью, мы можем воспользоваться композицией и переиспользовать наш StructuredLoggingInterpolatedStringHandler внутри этих обработчиков. Пример такого обработчика приведен под спойлером:

[InterpolatedStringHandler]
public ref struct StructuredLoggingErrorInterpolatedStringHandler
{
    private readonly StructuredLoggingInterpolatedStringHandler _handler;

    public StructuredLoggingErrorInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, out bool isEnabled)
    {
        _handler = new StructuredLoggingInterpolatedStringHandler(literalLength, formattedCount, logger, LogLevel.Error, out isEnabled);
    }

    public bool IsEnabled => _handler.IsEnabled;

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public void AppendLiteral(string s) => _handler.AppendLiteral(s);

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public void AppendFormatted<T>(T value, [CallerArgumentExpression("value")] string name = "") => _handler.AppendFormatted(value, name);

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public (string, object?[]) GetTemplateAndArguments() => _handler.GetTemplateAndArguments();
}

public static void LogError(this ILogger logger, [InterpolatedStringHandlerArgument("logger")] ref StructuredLoggingErrorInterpolatedStringHandler handler)
{
    if (handler.IsEnabled)
    {
        var (template, arguments) = handler.GetTemplateAndArguments();
        logger.LogError(template, arguments);
    }
}

Полный код проекта (с небольшими улучшениями) можно найти на GitHub.

Производительность

UPD: По просьбе @vabka добавил бенчмарки.

Для замера производительности воспользуемся BenchmarkDotNet. Будем использовать логирование в Serilog с пустым логгером. Результаты выглядят следующим образом:

В этой таблице:

• Template and Args - обычный сырой вызов LogInformation(string, object[]).

• Interpolated Handler - наш код с интерполяцией.

• Logger Message Delegate - закэшированный делегат, созданный при помощи LoggerMessage.Define. Этот способ использует и генератор исходного кода (source generator).

• Formattable String * - различные способы из библиотеки https://github.com/Drizin/InterpolatedLogging, на которую любезно указал в комментариях @vabka

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

При включенном уровне логирования, наш метод примерно на 7-10% медленне, чем использование сырого шаблона либо закэшированного делегата, но все равно существенно оптимальнее нежели https://github.com/Drizin/InterpolatedLogging.

Заключение

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

В коде все еще присутствуют некоторые проблемы, такие как отсутствие экранирования имен (так, Serilog требует, чтобы имена были правильными C#-идентификаторами) или неоптимальная реализация экранирования фигурных скобок. Если вы ищете готовое для использования решение, то можете обратить внимание на мою библиотеку ISLE, в которой решены все эти проблемы.

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

• https://github.com/fedarovich/isle

• https://habr.com/ru/post/266299/

• https://andrewlock.net/exploring-dotnet-6-part-8-improving-logging-performance-with-source-generators/

• https://docs.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator

• https://docs.microsoft.com/ru-ru/dotnet/csharp/whats-new/tutorials/interpolated-string-handler

• https://docs.microsoft.com/ru-ru/dotnet/api/system.runtime.compilerservices.callerargumentexpressionattribute?view=net-6.0