{"id":393874,"date":"2024-06-29T11:16:37","date_gmt":"2024-06-29T11:16:37","guid":{"rendered":"http:\/\/savepearlharbor.com\/?p=393874"},"modified":"-0001-11-30T00:00:00","modified_gmt":"-0001-11-29T21:00:00","slug":"","status":"publish","type":"post","link":"https:\/\/savepearlharbor.com\/?p=393874","title":{"rendered":"<span>Structured Logging and Interpolated Strings in C# 10<\/span>"},"content":{"rendered":"<div><!--[--><!--]--><\/div>\n<div id=\"post-content-body\">\n<div>\n<div class=\"article-formatted-body article-formatted-body article-formatted-body_version-2\">\n<div xmlns=\"http:\/\/www.w3.org\/1999\/xhtml\">\n<p>Structured logging is gaining more and more popularity in the developers&#8217; community. So it makes no surprise that Microsoft has added support for it to the Microsoft.Extensions.Logging package being the part of .Net Core\/.Net 5\/.Net 6. In this article I&#8217;d like to demonstrate how we can use structured logging with this package and show the idea how we can extend it using the new features of C# 10.<\/p>\n<h3>Initial Setup<\/h3>\n<p>Microsoft.Extensions.Logging is known to be a fa\u00e7ade supporting different pluggable underlying logging providers. In this article I will use the Serilog provider and will set it up to output logs to the console in JSON format.<\/p>\n<p>I will use simple console application as an example (<a href=\"https:\/\/github.com\/fedarovich\/interpolated-logging-demo\" rel=\"noopener noreferrer nofollow\">GitHub Link<\/a>). Logging configuration looks the following way:<\/p>\n<pre><code class=\"cs\">\/\/ Serilog configuration Log.Logger = new LoggerConfiguration()     .MinimumLevel.Information()     .WriteTo.Console(new CompactJsonFormatter())     .CreateLogger();     \/\/ Register Serilog while creating Microsoft.Extensions.Logging.LoggerFactory using var loggerFactory = LoggerFactory.Create(     builder => builder.AddSerilog(dispose: true)); \/\/ Create an instance of ILogger using the factory var logger = loggerFactory.CreateLogger(); <\/code><\/pre>\n<p>Let&#8217;s also create two records which will be used in the further examples:<\/p>\n<pre><code class=\"cs\">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);     } } <\/code><\/pre>\n<h3>Using ILogger<\/h3>\n<p>We will use the <code>ILogger<\/code> interface for logging. This interface provides several overloads of the <code>Log<\/code> method which take the log level as a parameter. It also provides overloads of methods <code>Log&lt;Level><\/code>, e.g. <code>LogInformation<\/code>, <code>LogError<\/code>, etc. All these method take the message template string and the array of arguments (<code>params object[]<\/code>) as their parameters.<\/p>\n<p>For example, let&#8217;s log the result of a segment length calculation:<\/p>\n<pre><code class=\"cs\">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); <\/code><\/pre>\n<p>The template string contains two arguments enclosed in braces: <code>segment<\/code> and <code>length<\/code>. Their values are passed to the method as the following parameters. The <code>@<\/code> symbol before the <code>segment<\/code> argument is a part of the <a href=\"https:\/\/messagetemplates.org\" rel=\"noopener noreferrer nofollow\">Message Template<\/a> specification which means that Serilog must expand the argument&#8217;s structure as an object. Without this symbol Serilog would just log the result of <code>segment.ToString()<\/code>.<\/p>\n<p>As the result we will get the following log item:<\/p>\n<pre><code class=\"json\">{     \"@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\" } <\/code><\/pre>\n<p>The resulting JSON object has a property <code>@mt<\/code> containing the template string, and properties <code>segment<\/code> and <code>length<\/code> containing the arguments.<\/p>\n<p>While this approach is quite easy and straightforward, it has some significant disadvantages:<\/p>\n<ul>\n<li>\n<p>It is necessary to parse the template string at runtime, but it&#8217;s a quite expensive operation. The logging infrastructure uses an <a href=\"https:\/\/github.com\/dotnet\/runtime\/blob\/57bfe474518ab5b7cfe6bf7424a79ce3af9d6657\/src\/libraries\/Microsoft.Extensions.Logging.Abstractions\/src\/FormattedLogValues.cs#L18\" rel=\"noopener noreferrer nofollow\">internal cache of 1024 string<\/a> to make this issue less significant.<\/p>\n<\/li>\n<li>\n<p>The memory is allocated for the arguments array even if the specified log level is disabled.<\/p>\n<\/li>\n<li>\n<p>Arguments of value types are boxed when being placed into the object array.<\/p>\n<\/li>\n<li>\n<p>Names of the variables are duplicated in the template string and in the method parameters.<\/p>\n<\/li>\n<li>\n<p>It is easy to forget some argument or use a wrong argument order.<\/p>\n<\/li>\n<\/ul>\n<p>.Net 6 provides a new source code generator as a better alternative without these disadvantages. We can declare a partial method taking the required parameters and mark it with the <code>LoggerMessageAttribute<\/code> as follows:<\/p>\n<pre><code class=\"cs\">[LoggerMessage(0, LogLevel.Information, \"The length of segment {segment} is {length}.\")] public static partial void LogSegmentLength(this ILogger logger, Segment segment, double length); <\/code><\/pre>\n<p>This approach provides the best logging performance, however it also has its own disadvantages:<\/p>\n<ul>\n<li>\n<p>It clutters up the source code with the partial method declarations.<\/p>\n<\/li>\n<li>\n<p>It does not allow to use the <code>@<\/code> symbol before the argument names, preventing Serilog from expanding them into JSON objects.<\/p>\n<\/li>\n<\/ul>\n<h3>Adding Support for Interpolated Strings to ILogger<\/h3>\n<p>So, we would like to find an expressive way to write structured logs without the mentioned disadvantages. String interpolation could be a convenient way to achieve it, but it will require some additional work from us.<\/p>\n<p>If we try to call a usual logging method with an interpolated string, e.g.:<\/p>\n<pre><code class=\"cs\">logger.LogInformation($\"The length of segment {segment} is {length}.\");<\/code><\/pre>\n<p>we will get the following log record:<\/p>\n<pre><code class=\"json\">{     \"@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\" } <\/code><\/pre>\n<p>As expected, we have lost information about the arguments because C# compiler has converted our interpolated string into a simple call to <code>String.Format<\/code>.<\/p>\n<p>Generally speaking, until C# 10 the compiler could transform the interpolated string to either a <code>FormattableString<\/code> instance or a simple string. <code>FormattableString<\/code> objects look almost like the thing we need to solve our problem, as they contain the format string and the argument array. Unfortunately, they still do not contain the argument names. Moreover, when the compiler chooses the method overload, it prefers one taking a string, that makes it no so convenient to use.<\/p>\n<p>Luckily, C# 10 provides a new mechanism for the interpolated strings which allows us to implement the solution. We can create a special struct that acts as an interpolated string handler and provides the required functionality especially for our use case:<\/p>\n<pre><code class=\"cs\">[InterpolatedStringHandler] public ref struct StructuredLoggingInterpolatedStringHandler {     \/\/ The actual code will be shown below } <\/code><\/pre>\n<p>Next, we can use it as a method argument. For example, let&#8217;s create a <code>Log<\/code> extension method:<\/p>\n<pre><code class=\"cs\">public static partial class LoggerExtensions {     public static void Log(this ILogger logger, LogLevel logLevel,          [InterpolatedStringHandlerArgument(\"logger\", \"logLevel\")] ref StructuredLoggingInterpolatedStringHandler handler)     {         \/\/ The actual code will be shown below     } } <\/code><\/pre>\n<p>If we try to pass an interpolated string to our <code>Log<\/code> method now:<\/p>\n<pre><code class=\"cs\">logger.Log(LogLevel.Information, $\"The length of segment {segment} is {length}.\"); <\/code><\/pre>\n<p>the compiler will transform it to the following code:<\/p>\n<pre><code class=\"cs\">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); <\/code><\/pre>\n<p>We can see that the compiler uses calls to the <code>AppendLiteral<\/code> method in order to add literal parts of the string and calls to the <code>AppendFormatted<\/code> method(s) for the arguments. Thus, we can write our handler in a way that it creates a template string to be passed into the original <code>ILogger.Log<\/code>, as well as the argument array.<\/p>\n<p>The next question is how we can get the names of the arguments. Fortunately, C# 10 provides another feature that can help us, namely <code>CallerArgumentExpressionAttribute<\/code>. Like with the other <code>Caller*<\/code>-attributes, if we mark an optional string parameter of the <code>AppendFormatted<\/code> method with this attribute, the compiler will pass the C# expression used for the other method&#8217;s parameter as this parameter&#8217;s value.<\/p>\n<p>So, let&#8217;s put everything together and write the code for our handler.<\/p>\n<p>First, we&#8217;ll declare fields for the message template and its arguments, as well as a property indicating whether the required log level is enabled:<\/p>\n<pre><code class=\"cs\">[InterpolatedStringHandler] public ref struct StructuredLoggingInterpolatedStringHandler {     private readonly StringBuilder _template = null!;     private readonly List&lt;object?> _arguments = null!;      public bool IsEnabled { get; }        \/\/ ... } <\/code><\/pre>\n<p>Next, we must create a constructor taking the length of the string literal, the number of arguments, the instance of <code>ILogger<\/code>, the log level and the output parameter <code>isEnabled<\/code>:<\/p>\n<pre><code class=\"cs\">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&lt;object?>(formattedCount);     } } <\/code><\/pre>\n<p>Note that we create <code>StringBuilder<\/code> and <code>List&lt;object?><\/code> only if the log level passed to the method is enabled.<\/p>\n<details class=\"spoiler\">\n<summary>Note<\/summary>\n<div class=\"spoiler__content\">\n<p>The source code in GitHub repository uses an optimized private collection instead of <code>List&lt;object?>.<\/code><\/p>\n<\/div>\n<\/details>\n<p>You might wonder how the compiler knows where it can get the <code>ILogger<\/code> and the log level from. If you look at the declaration of the <code>Log<\/code> method above, you can see that the handler parameter is marked with the <code>[InterpolatedStringHandlerArgument(\"logger\", \"logLevel\")]<\/code> attribute with two arguments. The arguments specify the names of the method parameters containing these values.<\/p>\n<p>Next, we will add the <code>AppendLiteral<\/code> method:<\/p>\n<pre><code class=\"cs\">public void AppendLiteral(string s) {     if (!IsEnabled)          return;      _template.Append(s.Replace(\"{\", \"{{\", StringComparison.Ordinal).Replace(\"}\", \"}}\", StringComparison.Ordinal)); } <\/code><\/pre>\n<p>I used two calls to <code>String.Replace<\/code> in order to escape the braces in this method. For sure, we could implement this escaping in a more optimal way, but let&#8217;s leave it as it is in this article for simplicity.<\/p>\n<p>Next, we will add the <code>AppendFormatted<\/code> method:<\/p>\n<pre><code class=\"cs\">public void AppendFormatted&lt;T>(     T value,      [CallerArgumentExpression(\"value\")] string name = \"\") {     if (!IsEnabled)         return;      _arguments.Add(value);     _template.Append($\"{{@{name}}}\"); } <\/code><\/pre>\n<p>As I mentioned before, it contains the optional <code>name<\/code> parameter marked with the <code>[CallerArgumentExpression(\"value\")]<\/code> attribute. The compiler will pass the string representation of the C# expression used for the <code>value<\/code> parameter as the value of this parameter (a variable name in the simplest case).<\/p>\n<p>Note that I always add the <code>@<\/code> symbol before the argument name. As far as I can see, Serilog handles it well even for primitive types. However, if it didn&#8217;t, we could always create separate overloads for such types.<\/p>\n<details class=\"spoiler\">\n<summary>StringBuilder.Append<\/summary>\n<div class=\"spoiler__content\">\n<p>By the way, this method uses a new overload <code>StringBuilder.Append(ref System.Text.StringBuilder.AppendInterpolatedStringHandler handler)<\/code>. This overload also uses the new string interpolation mechanism. <\/p>\n<\/div>\n<\/details>\n<p>At last, we will add a method that returns the built message template and the argument array:<\/p>\n<pre><code class=\"cs\">public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray()); <\/code><\/pre>\n<p>Our handler is ready! You can find its full source code under the spoiler:<\/p>\n<details class=\"spoiler\">\n<summary>Handler source code<\/summary>\n<div class=\"spoiler__content\">\n<pre><code class=\"cs\">[InterpolatedStringHandler] public ref struct StructuredLoggingInterpolatedStringHandler {     private readonly StringBuilder _template = null!;     private readonly List&lt;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&lt;T>(         T value,          [CallerArgumentExpression(\"value\")] string name = \"\")     {         if (!IsEnabled)             return;          _arguments.Add(value);         _template.Append($\"{{@{name}}}\");     }      public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray()); } <\/code><\/pre>\n<\/p>\n<\/div>\n<\/details>\n<p>Our <code>Log<\/code> method can use it in the following way:<\/p>\n<pre><code class=\"cs\">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);         }     } } <\/code><\/pre>\n<p>Now we can use it to perform logging:<\/p>\n<pre><code class=\"cs\">logger.Log(LogLevel.Information, $\"The length of segment {segment} is {length}.\");<\/code><\/pre>\n<p>We will get a correct log record as the result:<\/p>\n<pre><code class=\"json\">{     \"@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\" } <\/code><\/pre>\n<p>By the way, note that the method overload taking the handler has a priority over the one taking a string. In my humble opinion, this behavior is much more correct than the one we have had with <code>FormattableString<\/code> overloads since C# 6.<\/p>\n<p>So, now we have an extension method letting us write to the logs with the log level specified in one of the parameters. We would also like to have methods specific for each log level like <code>LogError<\/code>. We can create them in the same way, however our original handler requires the log level passed as one of the parameters. Thus, we will have to create a separate handler for each log level. Luckily, we can use composition and reuse our <code>StructuredLoggingInterpolatedStringHandler<\/code> inside these handlers, e.g.:<\/p>\n<details class=\"spoiler\">\n<summary>Handler source code  <\/summary>\n<div class=\"spoiler__content\">\n<pre><code class=\"cs\">[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&lt;T>(T value, [CallerArgumentExpression(\"value\")] string name = \"\") => _handler.AppendFormatted(value, name);      [MethodImpl(MethodImplOptions.AggressiveInlining)]     public (string, object?[]) GetTemplateAndArguments() => _handler.GetTemplateAndArguments(); } <\/code><\/pre>\n<\/p>\n<\/div>\n<\/details>\n<details class=\"spoiler\">\n<summary>Method source code  <\/summary>\n<div class=\"spoiler__content\">\n<pre><code class=\"cs\">public static void LogError(this ILogger logger, [InterpolatedStringHandlerArgument(\"logger\")] ref StructuredLoggingErrorInterpolatedStringHandler handler) {     if (handler.IsEnabled)     {         var (template, arguments) = handler.GetTemplateAndArguments();         logger.LogError(template, arguments);     } } <\/code><\/pre>\n<\/p>\n<\/div>\n<\/details>\n<p>The full source code of the demo project (with some improvements) can be found at <a href=\"https:\/\/github.com\/fedarovich\/interpolated-logging-demo\" rel=\"noopener noreferrer nofollow\">GitHub<\/a>.<\/p>\n<h3>Performance<\/h3>\n<p>I used BenchmarkDotNet to measure the performance. The result for logging to Serilog with an empty logger are the following:<\/p>\n<div>\n<div class=\"table\">\n<table>\n<tbody>\n<tr>\n<th>\n<p>Method<\/p>\n<\/th>\n<th>\n<p>Is Enabled<\/p>\n<\/th>\n<th>\n<p>Mean<\/p>\n<\/th>\n<th>\n<p>Error<\/p>\n<\/th>\n<th>\n<p>Std Dev<\/p>\n<\/th>\n<th>\n<p>Ratio<\/p>\n<\/th>\n<th>\n<p>Allocated<\/p>\n<\/th>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\"><strong>Template and Args<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>False<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>94.43 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>0.215 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>0.191 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>1.00<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>64 B<\/strong><\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Interpolated Handler<\/p>\n<\/td>\n<td>\n<p align=\"left\">False<\/p>\n<\/td>\n<td>\n<p align=\"left\">14.65 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.059 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.055 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.16<\/p>\n<\/td>\n<td>\n<p align=\"left\">&#8212;<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Logger Message Delegate<\/p>\n<\/td>\n<td>\n<p align=\"left\">False<\/p>\n<\/td>\n<td>\n<p align=\"left\">14.97 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.086 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.080 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.16<\/p>\n<\/td>\n<td>\n<p align=\"left\">&#8212;<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String<\/p>\n<\/td>\n<td>\n<p align=\"left\">False<\/p>\n<\/td>\n<td>\n<p align=\"left\">31.72 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.314 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.294 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.34<\/p>\n<\/td>\n<td>\n<p align=\"left\">96 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String NP<\/p>\n<\/td>\n<td>\n<p align=\"left\">False<\/p>\n<\/td>\n<td>\n<p align=\"left\">40.53 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.277 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.246 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.43<\/p>\n<\/td>\n<td>\n<p align=\"left\">160 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String Anonymous<\/p>\n<\/td>\n<td>\n<p align=\"left\">False<\/p>\n<\/td>\n<td>\n<p align=\"left\">34.67 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.286 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.268 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.37<\/p>\n<\/td>\n<td>\n<p align=\"left\">120 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<td>\n<p align=\"left\">\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\"><strong>Template and Args<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>True<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>4,048.28 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>11.917 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>11.147 ns<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>1.00<\/strong><\/p>\n<\/td>\n<td>\n<p align=\"left\"><strong>3,024 B<\/strong><\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Interpolated Handler<\/p>\n<\/td>\n<td>\n<p align=\"left\">True<\/p>\n<\/td>\n<td>\n<p align=\"left\">4,316.35 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">16.610 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">15.537 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">1.07<\/p>\n<\/td>\n<td>\n<p align=\"left\">3,400 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Logger Message Delegate<\/p>\n<\/td>\n<td>\n<p align=\"left\">True<\/p>\n<\/td>\n<td>\n<p align=\"left\">3,977.99 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">11.557 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">10.811 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">0.98<\/p>\n<\/td>\n<td>\n<p align=\"left\">2,984 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String<\/p>\n<\/td>\n<td>\n<p align=\"left\">True<\/p>\n<\/td>\n<td>\n<p align=\"left\">7,239.94 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">19.100 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">17.866 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">1.79<\/p>\n<\/td>\n<td>\n<p align=\"left\">7,673 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String NP<\/p>\n<\/td>\n<td>\n<p align=\"left\">True<\/p>\n<\/td>\n<td>\n<p align=\"left\">5,828.89 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">23.061 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">20.443 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">1.44<\/p>\n<\/td>\n<td>\n<p align=\"left\">5,672 B<\/p>\n<\/td>\n<\/tr>\n<tr>\n<td>\n<p align=\"left\">Formattable String Anonymous<\/p>\n<\/td>\n<td>\n<p align=\"left\">True<\/p>\n<\/td>\n<td>\n<p align=\"left\">6,402.80 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">22.911 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">21.431 ns<\/p>\n<\/td>\n<td>\n<p align=\"left\">1.58<\/p>\n<\/td>\n<td>\n<p align=\"left\">5,832 B<\/p>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n<\/div>\n<p>In this table:<\/p>\n<ul>\n<li>\n<p>Template and Args &#8212; a usual call of <code>LogInformation(string, object[])<\/code>.<\/p>\n<\/li>\n<li>\n<p>Interpolated Handler &#8212; our code with interpolated string handler.<\/p>\n<\/li>\n<li>\n<p>Logger Message Delegate &#8212; cached delegate created by <code>LoggerMessage.Define<\/code>. This approach is also used by the source generator.<\/p>\n<\/li>\n<li>\n<p>Formattable String * &#8212; different approaches from the <a href=\"https:\/\/github.com\/Drizin\/InterpolatedLogging\" rel=\"noopener noreferrer nofollow\">https:\/\/github.com\/Drizin\/InterpolatedLogging<\/a> library.<\/p>\n<\/li>\n<\/ul>\n<p>We can see, that if the log level is disabled, our approach is faster and allocates no wasted memory.<\/p>\n<p>If the log level is enabled, our approach is approximately 7-10% slower than using a raw template or a cached delegate, however it still performs much better than <a href=\"https:\/\/github.com\/Drizin\/InterpolatedLogging\" rel=\"noopener noreferrer nofollow\">https:\/\/github.com\/Drizin\/InterpolatedLogging<\/a>.<\/p>\n<h3>Conclusion<\/h3>\n<p>Using C# 10, we were able to add the structured logging support with string interpolation and get rid of the issues with the argument duplication, wrong argument number or order as well as wasting memory when the log level is disabled.<\/p>\n<p>The source code still has some issues like missing escaping of names (as Serilog requires the names to be valid C# identifiers) or suboptimal implementation in some places. You can find a production ready solution in my library called <a href=\"https:\/\/github.com\/fedarovich\/isle\" rel=\"noopener noreferrer nofollow\">ISLE<\/a>.<\/p>\n<h3>Useful Links<\/h3>\n<ul>\n<li>\n<p><a href=\"https:\/\/github.com\/fedarovich\/isle\" rel=\"noopener noreferrer nofollow\">https:\/\/github.com\/fedarovich\/isle<\/a><\/p>\n<\/li>\n<li>\n<p><a href=\"https:\/\/andrewlock.net\/exploring-dotnet-6-part-8-improving-logging-performance-with-source-generators\/\" rel=\"noopener noreferrer nofollow\">https:\/\/andrewlock.net\/exploring-dotnet-6-part-8-improving-logging-performance-with-source-generators\/<\/a><\/p>\n<\/li>\n<li>\n<p><a href=\"https:\/\/docs.microsoft.com\/en-us\/dotnet\/core\/extensions\/logger-message-generator\" rel=\"noopener noreferrer nofollow\">https:\/\/docs.microsoft.com\/en-us\/dotnet\/core\/extensions\/logger-message-generator<\/a><\/p>\n<\/li>\n<li>\n<p><a href=\"https:\/\/docs.microsoft.com\/en-us\/dotnet\/csharp\/whats-new\/tutorials\/interpolated-string-handler\" rel=\"noopener noreferrer nofollow\">https:\/\/docs.microsoft.com\/en-us\/dotnet\/csharp\/whats-new\/tutorials\/interpolated-string-handler<\/a><\/p>\n<\/li>\n<li>\n<p><a href=\"https:\/\/docs.microsoft.com\/en-us\/dotnet\/api\/system.runtime.compilerservices.callerargumentexpressionattribute?view=net-6.0\" rel=\"noopener noreferrer nofollow\">https:\/\/docs.microsoft.com\/en-us\/dotnet\/api\/system.runtime.compilerservices.callerargumentexpressionattribute?view=net-6.0<\/a><\/p>\n<\/li>\n<\/ul>\n<\/div>\n<\/div>\n<\/div>\n<p><!----><!----><\/div>\n<p><!----><!----><br \/> \u0441\u0441\u044b\u043b\u043a\u0430 \u043d\u0430 \u043e\u0440\u0438\u0433\u0438\u043d\u0430\u043b \u0441\u0442\u0430\u0442\u044c\u0438 <a href=\"https:\/\/habr.com\/ru\/articles\/591171\/\"> https:\/\/habr.com\/ru\/articles\/591171\/<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"<div><!--[--><!--]--><\/div>\n<div id=\"post-content-body\">\n<div>\n<div class=\"article-formatted-body article-formatted-body article-formatted-body_version-2\">\n<div xmlns=\"http:\/\/www.w3.org\/1999\/xhtml\">\n<p>Structured logging is gaining more and more popularity in the developers&#8217; community. So it makes no surprise that Microsoft has added support for it to the Microsoft.Extensions.Logging package being the part of .Net Core\/.Net 5\/.Net 6. In this article I&#8217;d like to demonstrate how we can use structured logging with this package and show the idea how we can extend it using the new features of C# 10.<\/p>\n<h3>Initial Setup<\/h3>\n<p>Microsoft.Extensions.Logging is known to be a fa\u00e7ade supporting different pluggable underlying logging providers. In this article I will use the Serilog provider and will set it up to output logs to the console in JSON format.<\/p>\n<p>I will use simple console application as an example (<a href=\"https:\/\/github.com\/fedarovich\/interpolated-logging-demo\" rel=\"noopener noreferrer nofollow\">GitHub Link<\/a>). Logging configuration looks the following way:<\/p>\n<pre><code class=\"cs\">\/\/ Serilog configuration Log.Logger = new LoggerConfiguration()     .MinimumLevel.Information()     .WriteTo.Console(new CompactJsonFormatter())     .CreateLogger();     \/\/ Register Serilog while creating Microsoft.Extensions.Logging.LoggerFactory using var loggerFactory = LoggerFactory.Create(     builder => builder.AddSerilog(dispose: true)); \/\/ Create an instance of ILogger using the factory var logger = loggerFactory.CreateLogger(); <\/code><\/pre>\n<p>Let&#8217;s also create two records which will be used in the further examples:<\/p>\n<pre><code class=\"cs\">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);     } } <\/code><\/pre>\n<h3>Using ILogger<\/h3>\n<p>We will use the <code>ILogger<\/code> interface for logging. This interface provides several overloads of the <code>Log<\/code> method which take the log level as a parameter. It also provides overloads of methods <code>Log&lt;Level><\/code>, e.g. <code>LogInformation<\/code>, <code>LogError<\/code>, etc. All these method take the message template string and the array of arguments (<code>params object[]<\/code>) as their parameters.<\/p>\n<p>For example, let&#8217;s log the result of a segment length calculation:<\/p>\n<pre><code class=\"cs\">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); <\/code><\/pre>\n<p>The template string contains two arguments enclosed in braces: <code>segment<\/code> and <code>length<\/code>. Their values are passed to the method as the following parameters. The <code>@<\/code> symbol before the <code>segment<\/code> argument is a part of the <a href=\"https:\/\/messagetemplates.org\" rel=\"noopener noreferrer nofollow\">Message Template<\/a> specification which means that Serilog must expand the argument&#8217;s structure as an object. Without this symbol Serilog would just log the result of <code>segment.ToString()<\/code>.<\/p>\n<p>As the result we will get the following log item:<\/p>\n<pre><code class=\"json\">{     \"@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\" } <\/code><\/pre>\n<p>The resulting JSON object has a property <code>@mt<\/code> containing the template string, and properties <code>segment<\/code> and <code>length<\/code> containing the arguments.<\/p>\n<p>While this approach is quite easy and straightforward, it has some significant disadvantages:<\/p>\n<ul>\n<li>\n<p>It is necessary to parse the template string at runtime, but it&#8217;s a quite expensive operation. The logging infrastructure uses an <a href=\"https:\/\/github.com\/dotnet\/runtime\/blob\/57bfe474518ab5b7cfe6bf7424a79ce3af9d6657\/src\/libraries\/Microsoft.Extensions.Logging.Abstractions\/src\/FormattedLogValues.cs#L18\" rel=\"noopener noreferrer nofollow\">internal cache of 1024 string<\/a> to make this issue less significant.<\/p>\n<\/li>\n<li>\n<p>The memory is allocated for the arguments array even if the specified log level is disabled.<\/p>\n<\/li>\n<li>\n<p>Arguments of value types are boxed when being placed into the object array.<\/p>\n<\/li>\n<li>\n<p>Names of the variables are duplicated in the template string and in the method parameters.<\/p>\n<\/li>\n<li>\n<p>It is easy to forget some argument or use a wrong argument order.<\/p>\n<\/li>\n<\/ul>\n<p>.Net 6 provides a new source code generator as a better alternative without these disadvantages. We can declare a partial method taking the required parameters and mark it with the <code>LoggerMessageAttribute<\/code> as follows:<\/p>\n<pre><code class=\"cs\">[LoggerMessage(0, LogLevel.Information, \"The length of segment {segment} is {length}.\")] public static partial void LogSegmentLength(this ILogger logger, Segment segment, double length); <\/code><\/pre>\n<p>This approach provides the best logging performance, however it also has its own disadvantages:<\/p>\n<ul>\n<li>\n<p>It clutters up the source code with the partial method declarations.<\/p>\n<\/li>\n<li>\n<p>It does not allow to use the <code>@<\/code> symbol before the argument names, preventing Serilog from expanding them into JSON objects.<\/p>\n<\/li>\n<\/ul>\n<h3>Adding Support for Interpolated Strings to ILogger<\/h3>\n<p>So, we would like to find an expressive way to write structured logs without the mentioned disadvantages. String interpolation could be a convenient way to achieve it, but it will require some additional work from us.<\/p>\n<p>If we try to call a usual logging method with an interpolated string, e.g.:<\/p>\n<pre><code class=\"cs\">logger.LogInformation($\"The length of segment {segment} is {length}.\");<\/code><\/pre>\n<p>we will get the following log record:<\/p>\n<pre><code class=\"json\">{     \"@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\" } <\/code><\/pre>\n<p>As expected, we have lost information about the arguments because C# compiler has converted our interpolated string into a simple call to <code>String.Format<\/code>.<\/p>\n<p>Generally speaking, until C# 10 the compiler could transform the interpolated string to either a <code>FormattableString<\/code> instance or a simple string. <code>FormattableString<\/code> objects look almost like the thing we need to solve our problem, as they contain the format string and the argument array. Unfortunately, they still do not contain the argument names. Moreover, when the compiler chooses the method overload, it prefers one taking a string, that makes it no so convenient to use.<\/p>\n<p>Luckily, C# 10 provides a new mechanism for the interpolated strings which allows us to implement the solution. We can create a special struct that acts as an interpolated string handler and provides the required functionality especially for our use case:<\/p>\n<pre><code class=\"cs\">[InterpolatedStringHandler] public ref struct StructuredLoggingInterpolatedStringHandler {     \/\/ The actual code will be shown below } <\/code><\/pre>\n<p>Next, we can use it as a method argument. For example, let&#8217;s create a <code>Log<\/code> extension method:<\/p>\n<pre><code class=\"cs\">public static partial class LoggerExtensions {     public static void Log(this ILogger logger, LogLevel logLevel,          [InterpolatedStringHandlerArgument(\"logger\", \"logLevel\")] ref StructuredLoggingInterpolatedStringHandler handler)     {         \/\/ The actual code will be shown below     } } <\/code><\/pre>\n<p>If we try to pass an interpolated string to our <code>Log<\/code> method now:<\/p>\n<pre><code class=\"cs\">logger.Log(LogLevel.Information, $\"The length of segment {segment} is {length}.\"); <\/code><\/pre>\n<p>the compiler will transform it to the following code:<\/p>\n<pre><code class=\"cs\">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); <\/code><\/pre>\n<p>We can see that the compiler uses calls to the <code>AppendLiteral<\/code> method in order to add literal parts of the string and calls to the <code>AppendFormatted<\/code> method(s) for the arguments. Thus, we can write our handler in a way that it creates a template string to be passed into the original <code>ILogger.Log<\/code>, as well as the argument array.<\/p>\n<p>The next question is how we can get the names of the arguments. Fortunately, C# 10 provides another feature that can help us, namely <code>CallerArgumentExpressionAttribute<\/code>. Like with the other <code>Caller*<\/code>-attributes, if we mark an optional string parameter of the <code>AppendFormatted<\/code> method with this attribute, the compiler will pass the C# expression used for the other method&#8217;s parameter as this parameter&#8217;s value.<\/p>\n<p>So, let&#8217;s put everything together and write the code for our handler.<\/p>\n<p>First, we&#8217;ll declare fields for the message template and its arguments, as well as a property indicating whether the required log level is enabled:<\/p>\n<pre><code class=\"cs\">[InterpolatedStringHandler] public ref struct StructuredLoggingInterpolatedStringHandler {     private readonly StringBuilder _template = null!;     private readonly List&lt;object?> _arguments = null!;      public bool IsEnabled { get; }        \/\/ ... } <\/code><\/pre>\n<p>Next, we must create a constructor taking the length of the string literal, the number of arguments, the instance of <code>ILogger<\/code>, the log level and the output parameter <code>isEnabled<\/code>:<\/p>\n<pre><code class=\"cs\">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&lt;object?>(formattedCount);     } } <\/code><\/pre>\n<p>Note that we create <code>StringBuilder<\/code> and <code>List&lt;object?><\/code> only if the log level passed to the method is enabled.<\/p>\n<details class=\"spoiler\">\n<summary>Note<\/summary>\n<div class=\"spoiler__content\">\n<p>The source code in GitHub repository uses an optimized private collection instead of <code>List&lt;object?>.<\/code><\/p>\n<\/div>\n<\/details>\n<p>You might wonder how the compiler knows where it can get the <code>ILogger<\/code> and the log level from. If you look at the declaration of the <code>Log<\/code> method above, you can see that the handler parameter is marked with the <code>[InterpolatedStringHandlerArgument(\"logger\", \"logLevel\")]<\/code> attribute with two arguments. The arguments specify the names of the method parameters containing these values.<\/p>\n<p>Next, we will add the <code>AppendLiteral<\/code> method:<\/p>\n<pre><code class=\"cs\">public void AppendLiteral(string s) {     if (!IsEnabled)          return;      _template.Append(s.Replace(\"{\", \"{{\", StringComparison.Ordinal).Replace(\"}\", \"}}\", StringComparison.Ordinal)); } <\/code><\/pre>\n<p>I used two calls to <code>String.Replace<\/code> in order to escape the braces in this method. For sure, we could implement this escaping in a more optimal way, but let&#8217;s leave it as it is in this article for simplicity.<\/p>\n<p>Next, we will add the <code>AppendFormatted<\/code> method:<\/p>\n<pre><code class=\"cs\">public void AppendFormatted&lt;T>(     T value,      [CallerArgumentExpression(\"value\")] string name = \"\") {     if (!IsEnabled)         return;<\/code><\/pre>\n<\/div>\n<\/div>\n<\/div>\n<\/div>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[],"tags":[],"class_list":["post-393874","post","type-post","status-publish","format-standard","hentry"],"_links":{"self":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/393874","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=393874"}],"version-history":[{"count":0,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/393874\/revisions"}],"wp:attachment":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=393874"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=393874"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=393874"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}