Структурное логирование и интерполированные строки в 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