High-Performance Logging
The LoggerMessage source generator writes your log call for you, with no array allocation and no boxing at the call site.
[LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "text {value}")] static partial void Name(ILogger logger, int value);An ordinary call such as logger.LogInformation("order {OrderId} shipped", orderId) does some work before the logger decides whether anyone wants the line. The arguments are collected into an object?[] array, and a value type like int is boxed to fit that array: a copy is made on the heap. On a path that runs ten thousand times a second, that is rubbish you paid to create and then threw away.
What the generator does
Put the [LoggerMessage] attribute on a partial method that returns void and lives in a partial class. At build time the LoggerMessage source generator writes the body. The generated code calls IsEnabled first, and carries the values in a generated struct rather than an array, so on a disabled level almost nothing happens, and on an enabled level there is no array and no boxing at the call site.
What else it buys
The level, the event id and the template sit in one declaration instead of being repeated at every call. The generator matches each placeholder to the parameter with the same name, so a typo in the template is a build error rather than a missing field at three in the morning. The generated code uses no reflection, which suits trimmed and ahead-of-time compiled builds.
When it is worth the ceremony
Use it on hot paths, on per-item logs inside loops, and on Debug or Trace lines that are usually switched off but still cost on every call. Six startup lines do not need it.
Example
// dotnet add package Microsoft.Extensions.Logging.Console
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;
using ILoggerFactory factory = LoggerFactory.Create(builder =>
{
builder.SetMinimumLevel(LogLevel.Information);
builder.AddSimpleConsole(options =>
{
options.ColorBehavior = LoggerColorBehavior.Disabled;
});
});
ILogger logger = factory.CreateLogger("Orders");
// Generated method, and the hand-written call it replaces. Same level,
// same event id, same template, same output.
Log.OrderShipped(logger, 7, "Leeds");
logger.Log(LogLevel.Information, new EventId(1, "OrderShipped"),
"order {orderId} shipped to {city}", 7, "Leeds");
static partial class Log
{
// Placeholder names match the parameter names below.
[LoggerMessage(EventId = 1, Level = LogLevel.Information,
Message = "order {orderId} shipped to {city}")]
public static partial void OrderShipped(ILogger logger, int orderId, string city);
}
// Output:
// info: Orders[1]
// order 7 shipped to Leeds
// info: Orders[1]
// order 7 shipped to LeedsWhen to use it
- Log one line per message in a queue consumer that handles thousands a second.
- Keep Trace logging in a tight loop that is switched off in production but still compiled in.
- Remove reflection-based logging from a trimmed or ahead-of-time compiled service.
More examples
An instance method that finds the logger itself
For an instance method the generator can take the logger from an ILogger field on the type, so the call site stays short. The class must still be partial. This is the usual shape inside a service: the log methods sit next to the code that uses them and nobody has to pass the logger around.
using Microsoft.Extensions.Logging;
public partial class PaymentService
{
private readonly ILogger<PaymentService> _logger;
public PaymentService(ILogger<PaymentService> logger)
{
_logger = logger;
}
// No ILogger parameter: the generator uses the field above.
[LoggerMessage(EventId = 12, Level = LogLevel.Warning,
Message = "payment {paymentId} retried, attempt {attempt}")]
private partial void PaymentRetried(string paymentId, int attempt);
public void Retry(string paymentId, int attempt)
{
PaymentRetried(paymentId, attempt);
}
}The longhand this replaced
You will still meet this in older code bases, so it is worth recognising. It avoids the same array and boxing, by hand, with the types written twice and the level far from the call. The attribute version generates code very like it. Do not write new code this way; do not rush to rewrite code that already works this way either.
using Microsoft.Extensions.Logging;
public static class OldStyleLog
{
// Before the generator, this was the fast path: build the delegate once,
// then call it. LoggerMessage.Define<int, string> returns an
// Action<ILogger, int, string, Exception?>.
private static readonly Action<ILogger, int, string, Exception?> s_orderShipped =
LoggerMessage.Define<int, string>(
LogLevel.Information,
new EventId(1, "OrderShipped"),
"order {orderId} shipped to {city}");
public static void OrderShipped(ILogger logger, int orderId, string city)
{
s_orderShipped(logger, orderId, city, null);
}
}Skipping the generated level check
One check outside the loop instead of one per item. Reach for SkipEnabledCheck only in this shape, where the call is already guarded. Set it anywhere else and the line is formatted and written even when the level is switched off, which is worse than the ordinary call you were trying to improve on.
using Microsoft.Extensions.Logging;
public static partial class TraceLog
{
// SkipEnabledCheck = true tells the generator not to emit IsEnabled.
// Only safe because the caller below checks it first.
[LoggerMessage(EventId = 90, Level = LogLevel.Trace,
Message = "row {rowId} scored {score}", SkipEnabledCheck = true)]
public static partial void RowScored(ILogger logger, int rowId, double score);
public static void ScoreAll(ILogger logger, IReadOnlyList<int> rowIds)
{
if (!logger.IsEnabled(LogLevel.Trace))
{
return;
}
foreach (int rowId in rowIds)
{
RowScored(logger, rowId, rowId * 0.5);
}
}
}
Discussion