High-Performance Logging: LoggerMessage Source Generator, IsEnabled ve Allocation Maliyeti

Sürüm notu: Bu yazıdaki kodlar .NET 10, Microsoft.Extensions.Telemetry.Abstractions 10.11 ve BenchmarkDotNet 0.15.8 ile derlenip denenmiştir.

Önce Tahmin Et

Production'da minimum seviye Information. Sepet service'inde şu satır var: logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", cartId, itemCount, total). Debug kapalı, yani bu satır hiçbir yere yazılmayacak. Peki her çağrıda bellekte hiç allocation yapılıyor mu? Yapılıyorsa kaç byte? Bir de şunu tahmin et: aynı satırı Information seviyesinde, açıkken yazdığında, message template'li çağrı mı daha hızlıdır, yoksa CA2254'ün kızdığı $"..." interpolation'ı mı?

İkinci sorunun cevabı çoğu kişiyi şaşırtıyor. İkisini de BenchmarkDotNet ile ölçeceğiz.

Kapalı Seviyede Bile Ödenen Bedel

ASP.NET Core Web API (Application Programming Interface) serisinin "ASP.NET Core'da Logging: ILogger, Log Seviyeleri, Structured Logging ve Serilog" yazısında LoggerMessage source generator'ına kısaca girmiş, "pahalı argümanları IsEnabled ile koru" demiştik. Bu yazı o girişin derinlemesine hâli: neden pahalı, ne kadar pahalı ve ekipte nasıl bir düzen kurmalı.

LogDebug, LogInformation ve kardeşleri ILogger üzerinde extension method'lar. İmzaları şöyle: LogDebug(this ILogger logger, string? message, params object?[] args). Bu imza, method'un içine girilmeden önce ödenen iki bedeli saklıyor. Birincisi params object?[]: her çağrıda yeni bir array oluşturulur. İkincisi boxing: int ve decimal gibi value type'lar object'e dönüştürülürken heap'te birer kutuya konur. Bunların hepsi çağrı noktasında, seviye kontrolünden önce yapılır. Logger daha sonra "Debug kapalı" deyip satırı atsa bile array ve kutular oluşmuş, garbage collector'a iş çıkmıştır.

Klasik çözüm, çağrıyı if (logger.IsEnabled(LogLevel.Debug)) ile sarmak. Çalışır, ama her log satırına üç satır if eklemek kimsenin sürdürebileceği bir disiplin değil. Daha temiz yol, kontrolü ve tipli parametreleri derleyiciye ürettirmek.

[LoggerMessage] ile Event Kataloğu

Serinin ilk yazısında Bookstore sipariş akışını üç event'e indirmiştik. Şimdi o event'leri ve sepet özetini tek bir static partial class'ta topluyoruz:

using Microsoft.Extensions.Logging;

namespace Bookstore.Orders;

// Event kataloğu: siparişle ilgili bütün log event'leri burada, id'ler class içinde tekil.
public static partial class OrderLog
{
    [LoggerMessage(EventId = 1001, Level = LogLevel.Information,
        Message = "Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}")]
    public static partial void OrderPlaced(this ILogger logger, Guid orderId, int customerId, int lineCount, decimal orderTotal);

    [LoggerMessage(EventId = 1002, Level = LogLevel.Information,
        Message = "Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})")]
    public static partial void OrderRejected(this ILogger logger, int customerId, string rejectReason, string isbn, int requested, int available);

    [LoggerMessage(EventId = 1003, Level = LogLevel.Warning,
        Message = "Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts")]
    public static partial void PaymentRetried(this ILogger logger, int customerId, int paymentAttempts);

    [LoggerMessage(EventId = 1004, Level = LogLevel.Debug,
        Message = "Cart {CartId} has {ItemCount} items, total {CartTotal}")]
    public static partial void CartSummary(this ILogger logger, int cartId, int itemCount, decimal cartTotal);
}

Çağıran taraf artık logger.OrderPlaced(order.Id, order.CustomerId, request.Lines.Count, order.Total) yazıyor. Template metni, seviye ve EventId tek bir yerde; çağrı noktasında yanlış seviye seçmek ya da placeholder adını farklı yazmak mümkün değil. Method adı da EventName oluyor: EventId'yi verip EventName'i vermediğinde generator nameof(OrderPlaced) kullanıyor. JSON (JavaScript Object Notation) console çıktısı, ilk yazıdaki elle yazılmış hâliyle birebir aynı:

{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders","Message":"Order 01a1b8de-8d15-7651-b472-6d4f3064e0f6 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d15-7651-b472-6d4f3064e0f6","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}

Aynı programda hemen ardından çağrılan logger.CartSummary(7, 3, 120.5m) hiç çıktı üretmedi, çünkü minimum seviye Information. Asıl soru, bu sessizliğin bedeli.

Generator Ne Üretiyor?

Projeye <EmitCompilerGeneratedFiles>true</EmitCompilerGeneratedFiles> eklersen üretilen kod obj/Debug/net10.0/generated/ altına yazılır. CartSummary için üretilen kod (dosyadan aynen):

private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::System.Int32, global::System.Int32, global::System.Decimal, global::System.Exception?> __CartSummaryCallback =
    global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.Int32, global::System.Int32, global::System.Decimal>(global::Microsoft.Extensions.Logging.LogLevel.Debug, new global::Microsoft.Extensions.Logging.EventId(1004, nameof(CartSummary)), "Cart {CartId} has {ItemCount} items, total {CartTotal}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });

[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "10.0.15.2326")]
public static partial void CartSummary(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.Int32 cartId, global::System.Int32 itemCount, global::System.Decimal cartTotal)
{
    if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Debug))
    {
        __CartSummaryCallback(logger, cartId, itemCount, cartTotal, null);
    }
}

Üç şey dikkat çekiyor. Template bir kez, class yüklenirken LoggerMessage.Define ile parse edilip static bir delegate'e çevriliyor; her çağrıda template parse edilmiyor. Parametreler int, int, decimal olarak tipli kalıyor; ne object[] var ne boxing. Ve IsEnabled kontrolü method'un ilk satırında, yani kapalı seviyede delegate'e hiç girilmiyor.

SkipEnabledCheck = true verdiğinde o if kalkıyor ve method doğrudan delegate'i çağırıyor. Bu, kontrolü zaten çağıran tarafta yapıyorsan işe yarar; örneğin bir döngünün dışında bir kez IsEnabled sorup içeride yüzlerce satır yazıyorsan. Aksi hâlde dokunma; varsayılan davranış doğru olan.

Instance Method ve Primary Constructor

Event'i extension method yerine service'in kendi private method'u olarak da tanımlayabilirsin. Generator, class'ta ILogger tipinde bir field ya da primary constructor parametresi arar:

public sealed partial class CartService(ILogger<CartService> logger)
{
    public void Checkout(CheckoutInfo checkout)
    {
        CheckoutStarted(checkout.CartId);
    }

    // instance method: generator ILogger'ı primary constructor'da buluyor
    [LoggerMessage(EventId = 2001, Level = LogLevel.Information, Message = "Checkout started for cart {CartId}")]
    private partial void CheckoutStarted(int cartId);
}

Üretilen method gövdesinde logger.IsEnabled(...) doğrudan primary constructor parametresine başvuruyor. Primary constructor desteği .NET 9 ile geldi; daha önce generator yalnız field'ı görüyordu ve private readonly ILogger _logger = logger; satırını elle yazmak gerekiyordu.

Hangisini seçmeli? Extension method'lu katalog, aynı event'i birden fazla class'ın kullandığı durumlarda (sipariş event'lerini hem API'nin hem de bir background job'ın yazması gibi) ve "bütün event'lerimiz nerede?" sorusuna tek dosyayla cevap vermek istediğinde iyi. Instance method ise yalnız o service'e ait, dışarıya açılmaması gereken event'ler için daha derli toplu. Ekipte ikisinden birini kural yapmak, ikisini karışık kullanmaktan iyidir.

Ölçelim: BenchmarkDotNet

Gerçek bir sink'i taklit etmek için mesajı biçimlendirip atan bir provider yazdım; böylece açık seviyede biçimlendirme maliyeti de ölçülüyor:

[MemoryDiagnoser]
[SimpleJob(launchCount: 1, warmupCount: 5, iterationCount: 10)]
public class LoggingBenchmarks
{
    private ILogger _logger = null!;
    private ILoggerFactory _factory = null!;
    private readonly int _cartId = 7;
    private readonly int _itemCount = 3;
    private readonly decimal _total = 120.5m;

    [GlobalSetup]
    public void Setup()
    {
        // Information açık, Debug kapalı; provider her mesajı biçimlendirip atıyor
        _factory = LoggerFactory.Create(b => b
            .SetMinimumLevel(LogLevel.Information)
            .AddProvider(new FormattingNullProvider()));
        _logger = _factory.CreateLogger("Bookstore.Orders");
    }

    [Benchmark(Baseline = true)]
    public void Disabled_Extension() =>
        _logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);

    [Benchmark]
    public void Disabled_IsEnabledGuard()
    {
        if (_logger.IsEnabled(LogLevel.Debug))
        {
            _logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);
        }
    }

    [Benchmark]
    public void Disabled_SourceGenerated() => _logger.CartSummary(_cartId, _itemCount, _total);

    [Benchmark]
    public void Enabled_Interpolated() =>
        _logger.LogInformation($"Cart {_cartId} has {_itemCount} items, total {_total}");

    [Benchmark]
    public void Enabled_Extension() =>
        _logger.LogInformation("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);

    [Benchmark]
    public void Enabled_SourceGenerated() => _logger.CartSummaryInfo(_cartId, _itemCount, _total);
}

CartSummaryInfo, CartSummary'nin Information seviyesindeki ikizi (EventId 1005). dotnet run -c Release ile, Apple M5 (Arm64) işlemcili bir Mac'te, .NET 10.0.13 runtime'ı üzerinde alınan gerçek sonuç:

| Method                   | Mean       | Error     | StdDev    | Ratio | RatioSD | Gen0   | Allocated | Alloc Ratio |
|------------------------- |-----------:|----------:|----------:|------:|--------:|-------:|----------:|------------:|
| Disabled_Extension       | 19.6024 ns | 0.8057 ns | 0.5329 ns |  1.00 |    0.04 | 0.0153 |     128 B |        1.00 |
| Disabled_IsEnabledGuard  |  0.4106 ns | 0.0201 ns | 0.0105 ns |  0.02 |    0.00 |      - |         - |        0.00 |
| Disabled_SourceGenerated |  0.6254 ns | 0.3260 ns | 0.2156 ns |  0.03 |    0.01 |      - |         - |        0.00 |
| Enabled_Interpolated     | 40.9263 ns | 2.2785 ns | 1.5071 ns |  2.09 |    0.09 | 0.0105 |      88 B |        0.69 |
| Enabled_Extension        | 82.1528 ns | 1.6964 ns | 1.1221 ns |  4.19 |    0.12 | 0.0257 |     216 B |        1.69 |
| Enabled_SourceGenerated  | 46.7951 ns | 3.8526 ns | 2.5483 ns |  2.39 |    0.14 | 0.0105 |      88 B |        0.69 |

Baştaki ilk sorunun cevabı ilk satırda: kapalı Debug satırı her çağrıda 128 byte ayırıyor. Hesabı tutuyor: üç elemanlı object[] 48 byte, iki boxed int 24'er byte, boxed decimal 32 byte. Saniyede 10.000 istek alan ve istek başına beş böyle satır çalıştıran bir API, hiçbir şey loglamadan saniyede yaklaşık 6,4 MB çöp üretir. Source-generated hâli ve IsEnabled korumalı hâli ise sıfır allocation ve bir nanosaniyenin altında.

İkinci sorunun cevabı ilginç: açık seviyede interpolation (41 ns, 88 B), message template'li extension method'dan (82 ns, 216 B) iki kat hızlı. Çünkü interpolation tek bir string üretiyor; extension method ise array, boxing, template'in cache'ten bulunması ve biçimlendirme yapıyor. Ama interpolation bu hızı structured logging'i öldürerek kazanıyor ve kapalı seviyede de string'i yine üretiyor. Source-generated sürüm (47 ns, 88 B) ikisinin iyi yanını birleştiriyor: interpolation'a yakın hız, aynı allocation (88 byte'ın tamamı sink'in ürettiği mesaj string'i) ve property'ler korunuyor.

Bu sayılar mikro saniyenin de altında; tek bir log satırı için kimse uykusunu kaçırmamalı. Fark, saniyede on binlerce kez çalışan sıcak yollarda ve GC (Garbage Collector) baskısında ortaya çıkıyor.

[LogProperties]: Object'i Property'lere Açmak

Bazen tek tek parametre yerine bütün bir object'i loglamak istersin. Microsoft.Extensions.Telemetry.Abstractions paketi bunun için [LogProperties] attribute'unu getiriyor:

public sealed record CheckoutInfo(int CartId, int ItemCount, decimal Total, string CustomerEmail);

[LoggerMessage(EventId = 2002, Level = LogLevel.Information, Message = "Checkout completed")]
private partial void CheckoutCompleted([LogProperties] CheckoutInfo checkout);

Çıktı:

{"EventId":2002,"LogLevel":"Information","Category":"Bookstore.Orders.CartService","Message":"Checkout completed","State":{"Message":"checkout.CustomerEmail=ada@example.com,checkout.Total=120,5,checkout.ItemCount=3,checkout.CartId=7,{OriginalFormat}=Checkout completed","checkout.CustomerEmail":"ada@example.com","checkout.Total":120.5,"checkout.ItemCount":3,"checkout.CartId":7,"{OriginalFormat}":"Checkout completed"}}

Record'un her property'si checkout. önekiyle ayrı bir property oldu. Ve checkout.CustomerEmail da oldu: biri yarın record'a telefon numarası eklese o da sessizce log'a girer. Hassas alanları [LogPropertyIgnore] ile dışarıda bırakabilir, öneki OmitReferenceName ile kaldırabilirsin:

public sealed record SafeCheckoutInfo(
    int CartId,
    int ItemCount,
    decimal Total,
    [property: LogPropertyIgnore] string CustomerEmail);

public static partial class SafeCheckoutLog
{
    [LoggerMessage(EventId = 2003, Level = LogLevel.Information, Message = "Checkout completed")]
    public static partial void CheckoutCompleted(this ILogger logger,
        [LogProperties(OmitReferenceName = true)] SafeCheckoutInfo checkout);
}

{"EventId":2003,"LogLevel":"Information","Category":"Bookstore.Orders","Message":"Checkout completed","State":{"Message":"Total=120,5,ItemCount=3,CartId=7,{OriginalFormat}=Checkout completed","Total":120.5,"ItemCount":3,"CartId":7,"{OriginalFormat}":"Checkout completed"}}

Yok saymak tek seçenek değil; e-postayı maskeleyerek loglamak, yani redaction ve data classification, serinin "Log'larda Hassas Veri" yazısının konusu.

Burada gözden kaçan bir ayrıntı var: bu paketi projeye eklediğin anda, SDK'nın (Software Development Kit) LoggerMessage generator'ı yerine paketin kendi generator'ı (Microsoft.Gen.Logging) devreye giriyor ve bütün [LoggerMessage] method'larını o üretiyor. Yukarıdaki State içindeki "Message" alanı ve property'lerin ters sırası bu yüzden farklı. Üretilen kod da farklı: parametreleri KeyValuePair<string, object?> dizisine, yani boxing'le yazıyor. Aynı benchmark'ı bu paketle çalıştırdığımda kapalı seviye yine sıfır allocation'dı, ama açık seviye değişti:

| Enabled_SourceGenerated  | 56.8422 ns | 2.6046 ns | 1.7228 ns |  2.89 |    0.11 | 0.0200 |     168 B |        1.31 |

88 byte yerine 168 byte, 47 ns yerine 57 ns. Hâlâ extension method'dan (216 byte) iyi, ama "Telemetry paketini ekledim, hiçbir şey değişmedi" demek de doğru değil. Redaction ve enrichment gibi özelliklere ihtiyacın varsa bu bedel makul; yoksa paketi yalnız [LogProperties] için eklemeden önce düşün.

Derleyici Hatanı Yakalasın

Source generator'ın sessiz bir faydası da derleme zamanı kontrolü. Template'te {CartId} yazıp parametreye basketId adı verdiğimde aldığım gerçek çıktı:

Broken.cs(7,6): error SYSLIB1014: Template 'CartId' is not provided as argument to the logging method (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/syslib1014)
Broken.cs(8,79): warning SYSLIB1015: Argument 'basketId' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/syslib1015)

Extension method ile aynı hatayı yaptığında derleyici hiçbir şey demez; log'da property adı yanlış çıkar ve bunu ancak bir sorguda sonuç gelmediğinde fark edersin.

Her şeyi derleyici yakalamıyor. Dokümana göre aynı EventId'yi iki method'da kullanmak SYSLIB1006 uyarısı vermeli; benim .NET 10.0.402 SDK ile yaptığım build'de aynı class'ta iki method'a EventId = 3001 verdiğimde uyarı çıkmadı, generator iki method'u da sorunsuz üretti. EventId tekilliğini derleyiciye bırakma; kataloğu tek dosyada tutmak ve basit bir reflection testi yazmak daha güvenilir.

Üretimde Dikkat

EventId aralıklarını bounded context ya da modül bazında böl: siparişler 1000'ler, ödeme 2000'ler, envanter 3000'ler gibi. Log aracında EventId >= 1000 and EventId < 2000 filtresi tek başına "sipariş modülünün bütün log'ları" anlamına gelir. Bu, category'den bağımsız bir boyut; kod bir namespace'ten diğerine taşındığında da bozulmaz.

Bir EventId bir kez yayına çıktıysa onu başka bir anlam için tekrar kullanma. Log aracındaki kayıtlı sorgular, dashboard'lar ve alert'ler EventId'ye bağlı olabilir. Template metnini düzeltebilirsin; anlamı değişiyorsa yeni bir id ver.

CA1848 analyzer kuralını warning yapmak, ekibi source-generated method'lara yönlendirmenin en ucuz yolu. Ama her satırı dönüştürmeye çalışma: uygulama açılışında bir kez yazılan bir log için katalog method'u yazmak fayda getirmez. Sıcak yollara, yani istek başına çalışan ve döngü içindeki kodlara odaklan.

Ölçümü de kendi ortamında yap. Buradaki sayılar bir Apple M5'te ve sahte bir provider'la alındı; gerçek sink'in (Serilog, OpenTelemetry exporter) maliyeti bunun üstüne eklenir ve genellikle baskın olan odur. Sink tarafını serinin "Serilog Sink'leri" yazısında konuşacağız.

Sık Düşülen Tuzaklar

Birincisi, IsEnabled korumasının sadece pahalı argümanlar için gerektiğini sanmak. Ölçüm gösterdi ki üç basit sayı bile 128 byte demek; "pahalı" argüman, method çağrısı olmasa da boxing yüzünden pahalı.

İkincisi, source-generated method'a pahalı bir argüman vermek: logger.CartSummary(cart.Id, cart.Items.Count, CalculateTotal(cart)). Generator'ın IsEnabled kontrolü method'un içinde; CalculateTotal çağrı noktasında, kontrolden önce çalışır. Gerçekten pahalı bir hesap varsa çağrıyı yine IsEnabled ile sar.

Üçüncüsü, exception parametresi. Method imzasında Exception tipli bir parametre varsa generator onu template'e değil, log'un exception alanına koyar. Template'e exception için ayrıca bir placeholder yazma; generator buna uyarı veriyor, çünkü exception zaten log'un kendi alanında, stack trace'iyle birlikte taşınıyor.

Dördüncüsü, [LogProperties]'i büyük object graph'larda kullanmak. Transitive = true iç içe object'leri de açar; bir Order'ın bütün satırlarını ve müşterisini tek event'e döker. Event'in hacmi ve hassas veri riski birlikte büyür.

Beşincisi, generator'ın ürettiği kodu "sihir" sanıp hiç bakmamak. EmitCompilerGeneratedFiles'ı bir kez aç, oku, sonra kapat. Hangi generator'ın çalıştığını ve parametrelerin nasıl taşındığını görmek, yukarıdaki 88 ile 168 byte farkını anlamanın tek yolu.

Küçük Bir Deneme

★☆☆ Benchmark'a Disabled_Interpolated ekle: _logger.LogDebug($"Cart {_cartId} has {_itemCount} items, total {_total}"). Kapalı seviyede interpolation'ın kaç byte ayırdığını ölç ve Disabled_Extension ile karşılaştır.

★★☆ OrderLog'a Exception parametresi alan bir PaymentFailed event'i (EventId 1006, Error) ekle. Üretilen kodda exception'ın LoggerMessage.Define delegate'ine nasıl geçtiğini obj/.../generated altındaki dosyada bul.

★★★ Bütün [LoggerMessage] attribute'larını reflection ile tarayıp aynı assembly içinde tekrar eden EventId varsa başarısız olan bir unit test yaz. Testi, bu yazıdaki 3001 çakışmasıyla kırmızıya düşürüp sonra düzelt.

Event'lerimiz artık ucuz ve tutarlı. Bir sonraki yazıda bu event'leri taşıyacak altyapıya geçiyoruz: Serilog'u derinlemesine kurmak, bootstrap logger ile açılış hatalarını yakalamak, appsettings'ten yapılandırma, enricher'lar ve istek başına tek özet event üreten request logging.