Allocation ve GC Analizi: gc-verbose, Allocation Sampling, LOH ve Server GC/DATAS Ayarları

Sürüm notu: Bu yazıdaki kodlar .NET 10 (container'da runtime 10.0.15) ile derlenip denenmiştir; dotnet-trace ve dotnet-counters 10.0.750501, yük için k6 2.4.0, trace analizi için Microsoft.Diagnostics.Tracing.TraceEvent 3.2.8 kullanılmıştır.

Önce Tahmin Et

Bookstore'un muhasebe ekibi her sabah 200.000 siparişlik bir CSV (virgülle ayrılmış düz metin) dosyası indiriyor; dosya 12 MB. Ay sonunda sekiz kişi aynı anda indirmeye başlayınca servis yavaşlıyor. İki soru: tek bir indirme isteği managed heap'te kaç byte allocation yapıyor olabilir, 12 MB mı, 24 MB mı, 60 MB mı? Ve sorunu çözmek için hangi ayar daha çok işe yarar: GC'yi (garbage collector; kullanılmayan object'leri temizleyen runtime bileşeni) Server modundan Workstation moduna almak, DATAS'ı (Dynamic Adaptation To Application Sizes; heap'i uygulamanın ihtiyacına göre büyütüp küçülten GC modu) kapatmak, yoksa hiçbiri? Cevaplar ölçüm tablolarında.

Ne Zaman GC Sorunu? Vaka: CSV Export'u

Endpoint, gerçek projelerde sıkça gördüğüm hâliyle bütün dosyayı bellekte kuruyor:

// bütün dosya bellekte: StringBuilder -> string -> byte[]
app.MapGet("/api/reports/orders.csv", (OrderStore orders) =>
{
    StringBuilder csv = new();
    csv.Append(Header);
    foreach (Order order in orders.All)
    {
        csv.Append(CultureInfo.InvariantCulture,
            $"{order.Id},{order.CustomerId},{order.PlacedAt:O},{order.Total},{order.Status}\n");
    }

    byte[] bytes = Encoding.UTF8.GetBytes(csv.ToString());
    return Results.File(bytes, "text/csv", "orders.csv");
});

8 sanal kullanıcıyla 30 saniyelik k6 yükü verip aynı anda dotnet-counters collect ile System.Runtime'ı kaydettim. 5 saniyelik aralıkların medyanı: saniyede 92 istek, p95 123 ms; 4 CPU'nun 3,83'ü dolu; saniyede 5,5 GB allocation; dakikada 924 gen0, 882 gen1 ve 1.614 gen2 GC; zamanın yüzde 20,5'i GC pause'unda; son GC'de LOH (Large Object Heap; 85.000 byte ve üstü object'lerin ayrıldığı bölge) 170 MB (en yüksek 218 MB); GC'nin committed belleği 653 MB, working set 862 MB.

Bunlar bir GC sorununun imzası. Saniyede 27 gen2, yani her istekte en az bir tam GC; CPU'nun beşte biri thread'lerin durduğu pause'larda. 5,5 GB'ı 92 isteğe bölünce ilk tahmin sorusunun cevabı çıkıyor: istek başına yaklaşık 60 MB, dosya boyutunun beş katı. Normal bir API'de gen2 dakikada birkaç taneyi geçmez; gen2'nin bu kadar sık olmasının en yaygın nedeni LOH. LOH'a ayrılan object'ler gen2'nin parçası sayılıyor ve yalnızca gen2 GC'de toplanıyor; LOH'a yapılan allocation belli bir eşiği aşınca GC doğrudan gen2 tetikliyor.

Bu tabloyu okurken eski bir yanılgıya dikkat. .NET 8 ve öncesindeki "% Time in GC since last GC" counter'ı yalnızca son iki GC arasındaki aralığı anlatıyordu ve bir saniye yüzde 0, bir sonraki saniye yüzde 90 gösterebiliyordu. Yeni dotnet.gc.pause.time toplam pause süresi; aralıktaki artışını aralığın süresine bölünce gerçek oranı buluyorsun. Bir de background GC var: gen2'nin büyük kısmı uygulama thread'leri çalışırken arka planda yapılabiliyor, yani "GC çalışıyor" ile "thread'ler duruyor" aynı şey değil. Kullanıcının hissettiği pause.

gc-verbose: Allocation'ı Stack'e Bağlamak

Metric'ler çok allocation olduğunu söylüyor; kimin yaptığını trace söyler. dotnet-trace'in iki GC profile'ı var: gc-collect yalnızca GC'lerin başlangıç ve bitişini çok düşük maliyetle kaydediyor, gc-verbose buna allocation örneklerini ekliyor:

docker exec profseries-api dotnet-trace collect -p 1 --profile gc-verbose --duration 00:00:00:10 -o /tmp/export-gcv.nettrace

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x0000000000008003  Verbose(5)          --profile

gc-verbose'un örnekleri GCAllocationTick event'i: runtime, yaklaşık her 100 KB allocation'da bir, o eşiği aşan object'in tipini ve stack'ini yazıyor. 10 saniyelik trace 317 MB çıktı. Trace'i Windows'ta PerfView'in allocation stack görünümlerinde açabilirsin (06); ben tipe ve ilk Bookstore frame'ine göre küçük bir TraceEvent script'iyle topladım, böyle bir aracı yazmak da 06'nın konusu:

AllocationTick by type (events 167274, bytes 41.983.941.544)
   39,0%      681  System.String (Large)
   21,0%    83792  System.Char[] (Small)
   19,7%    79156  System.Text.StringBuilder (Small)
   19,5%      682  System.Byte[] (Large)
    0,4%     1584  System.IO.Pipelines.BufferSegment (Small)
AllocationTick by first Bookstore frame (events 167274, bytes 41.983.941.544)
   99,2%   164332  Bookstore.Api.Reports.ReportEndpoints+<>c.<MapReportEndpoints>b__1_1(class Bookstore.Api.Ordering.OrderStore)

Allocation'ın yüzde 99'u export handler'ında. Tip dağılımı kodu doğruluyor: csv.ToString()'in 24 MB'lık string'i (UTF-16 olduğu için 12 MB'lık metin bellekte iki katı) ve GetBytes'ın 12 MB'lık byte[]'i doğrudan LOH'a gidiyor; StringBuilder ise metni 8.000 karakterlik parçalar hâlinde tutuyor ve her parça yeni bir char[] ile yeni bir StringBuilder object'i demek. Toplam: istek başına iki büyük object ve binlerce küçük parça.

.NET 10'da Allocation Sampling

Yukarıdaki tabloda bir tuhaflık var: StringBuilder object'leri 48 byte civarında küçük object'ler ama allocation'ın yüzde 19,7'si onlara yazılmış. Bunun nedeni AllocationTick'in yöntemi: sabit bir başlangıçtan sabit adımla sayıyor ve eşiği hangi object aşarsa 100 KB'ın tamamını ona yazıyor. Kodda her char[] parçasının hemen arkasından bir StringBuilder ayrıldığı için eşik sık sık ona denk geliyor. dotnet/runtime'ın tasarım dokümanı da bu sorunu anlatıyor: periyodik allocation pattern'lerinde sabit adımlı örnekleme ciddi hata üretebiliyor.

.NET 10 runtime'ı bunun için ayrı bir event getirdi: AllocationSampled. Her byte'a bağımsız bir olasılık veren rastgele bir örnekleme; ortalama yine yaklaşık 100 KB'ta bir örnek, ama sabit adım yok ve her örnekten toplam allocation için istatistiksel olarak sağlam bir tahmin çıkarılabiliyor. dotnet-trace'te allocationsampling keyword'üyle açılıyor:

docker exec profseries-api dotnet-trace collect -p 1 --clrevents gc+allocationsampling --duration 00:00:00:10 -o /tmp/export-as.nettrace

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x0000080000000001  Informational(4)    --clrevents

Runtime 10.0.15'te event'ler geldi ve aynı yükte 10 saniyelik trace 18 MB çıktı, gc-verbose'un 317 MB'ına karşı. Tasarım dokümanındaki tahmin formülüyle (her örnek için boyut / (1 - q^boyut), q = 1 - 1/102400) hesapladığım dağılım:

AllocationSampling by type (events 173734, bytes 46.968.991.658)
   39,7%      775  System.String (Large)
   39,6%   168086  System.Char[] (Small)
   19,8%      775  System.Byte[] (Large)
    0,4%     1916  System.IO.Pipelines.BufferSegment (Small)
    0,1%      552  System.Text.StringBuilder (Small)
AllocationSampling by first Bookstore frame (events 173734, bytes 46.968.991.658)
   99,2%   170183  Bookstore.Api.Reports.ReportEndpoints+<>c.<MapReportEndpoints>b__1_1(class Bookstore.Api.Ordering.OrderStore)

StringBuilder object'leri yüzde 0,1'e indi, char[] parçaları gerçek paylarına (string kadar, 24 MB) çıktı. 10 saniyede 775 büyük string örneklenmiş; 24 MB'lık bir object'in örneklenme olasılığı neredeyse 1, yani o sürede gelen 775 isteğin her birinin string'i yakalanmış. Tahmini toplam 47 GB, saniyede 4,7 GB; counters'ın ölçtüğü 5,5 GB'a yakın (trace açıkken istek sayısı biraz düştü). Production'da allocation profili alacaksan önce bunu dene: hem daha doğru hem on yedi kat daha küçük dosya.

Düzeltme: Streaming ve ArrayPool<T>

Dosyanın tamamını bellekte kurmaya gerek yok; satırları yazdıkça response'a akıtmak yetiyor. Tek bir 64 KB'lık buffer'ı ArrayPool<byte>'tan kiralayıp satırları doğrudan UTF-8 olarak içine yazıyorum, dolunca response'a gönderiyorum:

// streaming: havuzdan kiralanan tek bir 64 KB buffer, doldukça response'a gönderiliyor
app.MapGet("/api/reports/orders-v2.csv", async (HttpContext context, OrderStore orders) =>
{
    context.Response.ContentType = "text/csv";
    context.Response.Headers.ContentDisposition = "attachment; filename=orders.csv";

    byte[] buffer = ArrayPool<byte>.Shared.Rent(64 * 1024);
    try
    {
        int used = Encoding.UTF8.GetBytes(Header, buffer);
        foreach (Order order in orders.All)
        {
            int written;
            while (!Utf8.TryWrite(buffer.AsSpan(used), CultureInfo.InvariantCulture,
                $"{order.Id},{order.CustomerId},{order.PlacedAt:O},{order.Total},{order.Status}\n", out written))
            {
                await context.Response.Body.WriteAsync(buffer.AsMemory(0, used), context.RequestAborted);
                used = 0;
            }

            used += written;
        }

        await context.Response.Body.WriteAsync(buffer.AsMemory(0, used), context.RequestAborted);
    }
    finally
    {
        ArrayPool<byte>.Shared.Return(buffer);
    }
});

Utf8.TryWrite (.NET 8 ile geldi) interpolated string'i ara bir string oluşturmadan doğrudan byte span'ine yazıyor; yer yetmezse false dönüyor, buffer'ı gönderip aynı satırı yeniden deniyorum. 64 KB'lık buffer LOH eşiğinin altında, ama asıl önemli olan her istekte yeni bir tane ayırmamak; kiralanan array'i finally'de geri vermek şart, yoksa havuz yerine her seferinde yeni array alırsın. İki endpoint'in çıktısının byte byte aynı olduğunu MD5 (dosya içeriğinden üretilen özet değeri) ile kontrol ettim. Aynı yük, her biri temiz bir container'da:

Allocation 400 kat, bellek dörtte bir azaldı; throughput ise yalnızca yüzde 23 arttı. Kalan sınır CPU: 200.000 satırı biçimlendirmek her istekte iş, ve 4 CPU'nun 3,3'ü hâlâ kullanımda. GC sorunu çözüldü, sıradaki darboğaz biçimlendirme; bunu da 03'teki gibi bir CPU profiliyle görürsün.

GC Modları ve Container Limiti

İkinci tahmin sorusu ayarlarla ilgiliydi. Önce runtime'ın ne seçtiğine bakmak lazım. Lab'a GC ayarlarını döndüren bir teşhis endpoint'i ekledim:

// runtime hangi GC modunu ve limitleri seçti?
app.MapGet("/diag/gc", () =>
{
    GCMemoryInfo info = GC.GetGCMemoryInfo();
    return Results.Ok(new
    {
        GCSettings.IsServerGC,
        LatencyMode = GCSettings.LatencyMode.ToString(),
        TotalAvailableMemoryMB = info.TotalAvailableMemoryBytes / 1024 / 1024,
        HeapSizeMB = info.HeapSizeBytes / 1024 / 1024,
        Config = GC.GetConfigurationVariables()
    });
});

{
    "isServerGC": true,
    "latencyMode": "Interactive",
    "totalAvailableMemoryMB": 1536,
    "config": {
        "ServerGC": true,
        "ConcurrentGC": true,
        "HeapCount": 4,
        "GCHeapHardLimit": 1610612736,
        "GCDynamicAdaptationMode": 1,
        "GCDTargetTCP": 2
    }
}

(Çıktıyı kısalttım.) Üç şey görünüyor. ASP.NET Core projelerinde Web SDK ServerGarbageCollection'ı varsayılan olarak açıyor; build çıktısındaki runtimeconfig.json'da "System.GC.Server": true satırı bu yüzden var. DATAS, .NET 9'dan beri Server GC'de varsayılan olarak açık (GCDynamicAdaptationMode: 1); heap sayısını sabit tutmak yerine yüke göre değiştiriyor ve heap'i uzun yaşayan verinin boyutuna yakın tutmaya çalışıyor. Container'a --memory 2g verdiğim için GC'nin heap için kullanabileceği üst sınır (GCHeapHardLimit) 1,5 GiB: limit konmuş bir ortamda varsayılan, limitin yüzde 75'i. Kubernetes'te pod'un memory limit'i aynı şekilde okunuyor; ayrıntısı Kubernetes serisinin 09. yazısında.

Aynı yavaş export'u üç modda, her seferinde temiz bir container'la ölçtüm. Modu değiştirmek için ortam değişkeni kullandım (DOTNET_gcServer=0, DOTNET_GCDynamicAdaptationMode=0):

DATAS'ı kapatmak pause oranını yarıya indirdi ama belleği neredeyse ikiye katladı ve throughput'u artırmadı; Workstation GC her ölçüde kötüleşti. Tahminin cevabı "hiçbiri": hiçbir ayar, kodu düzeltilmiş endpoint'in varsayılan ayarlarla verdiği sonuca (113 istek/sn, yüzde 0,1 pause, 234 MB) yaklaşmadı. GC ayarı, allocation'ı düzeltildikten sonra ince ayar için; bir allocation sorununu ayarla örtmeye çalışma.

Ayar gerektiğinde ortam değişkeni yerine projede tutmak daha izlenebilir. MSBuild property'leri ve runtimeconfig.template.json build sırasında runtimeconfig.json'a yazılıyor:

<PropertyGroup>
  <GarbageCollectionAdaptationMode>0</GarbageCollectionAdaptationMode>
  <ConcurrentGarbageCollection>true</ConcurrentGarbageCollection>
</PropertyGroup>

{
  "configProperties": {
    "System.GC.HeapHardLimitPercent": 60
  }
}

"configProperties": {
  "System.GC.HeapHardLimitPercent": 60,
  "System.GC.Concurrent": true,
  "System.GC.Server": true,
  "System.GC.DynamicAdaptationMode": 0
}

Ortam değişkenlerinde sayılar onaltılık (hex) yazılıyor, JSON'da ondalık; DOTNET_GCHeapHardLimitPercent=3C yüzde 60 demek. Bu ayarlar process açılırken bir kez okunuyor, çalışan process'te değiştirmek etkisiz.

Working Set ile GC Heap Aynı Şey Değil

Yukarıdaki tablolarda üç bellek sayısı var ve hepsi farklı. GC heap, son GC'de yaşayan object'lerin ve aradaki boşlukların toplamı. Committed, GC'nin işletim sisteminden aldığı ve tuttuğu bellek; heap'ten büyüktür çünkü GC bir sonraki allocation'lar için yer ayırır. Working set ise process'in fiziksel bellekteki bütün sayfaları: GC'nin committed belleği, JIT'in (Just-In-Time; kodu çalışma anında makine koduna çeviren derleyici) ürettiği kod, runtime'ın kendi yapıları, native kütüphaneler, thread stack'leri. Kubernetes ve Docker'ın OOM (bellek yetmeyince process'in sistem tarafından öldürülmesi) kararı GC heap'e değil, container'ın toplam bellek kullanımına bakar.

Bir ölçümde bunun pratik etkisini gördüm: aynı container'da önce yavaş export'u, hemen ardından düzeltilmiş sürümü çalıştırdığımda working set 685 MB'ta kaldı ve LOH 158 MB görünmeye devam etti. Düzeltilmiş sürüm hiç gen2 tetiklemediği için GC'nin o belleği toplayıp işletim sistemine geri vermesi için bir neden yoktu. Temiz container'da aynı endpoint 234 MB ile çalıştı. Yük bittikten sonra working set'in düşmemesi tek başına leak kanıtı değil; leak'i heap'in tekrarlanan ölçümlerde büyümesinden anlarsın (05).

Üretimde Dikkat

Production'da allocation profili için ilk tercih gc+allocationsampling: gc-verbose bu yükte saniyede 30 MB'tan fazla yazdı. Hangisini alırsan al, süreyi kısa tut ve sorunun yaşandığı yükte al; boşta alınan allocation profili sana açılıştaki cache doldurmayı gösterir. GC metric'lerinde ortalamaya değil dağılıma bak: aynı trace'teki 568 pause'un ortalaması 4,2 ms, ama p99'u 19 ms ve en uzunu 27 ms. p99 latency hedefin 50 ms ise asıl tehdit ortalama değil, o uzun pause'lar.

Container memory limit'i ile GC ayarlarını birlikte düşün. GCHeapHardLimit'i limitin çok yakınına çekersen native bellek ve kod için yer kalmaz ve OOM kill GC'den önce gelir; çok aşağı çekersen GC sık ve pahalı çalışır, sonunda OutOfMemoryException görürsün. Varsayılan yüzde 75 çoğu servis için makul; değiştirmeden önce working set ile committed arasındaki farkı ölç.

Sık Düşülen Tuzaklar

• GC.Collect() ile "düzeltmek": belleği bir anlığına düşürür, ama allocation hızını değiştirmez ve her çağrıda tam bir GC'nin pause'unu kullanıcıya ödetir. Allocation'ı azalt.
• Yalnızca ortalama pause'a bakmak; tail latency'yi uzun pause'lar belirler.
• LOH eşiğini (GCLOHThreshold) yükseltip sorunu taşımak: 24 MB'lık bir string hangi eşikte olursa olsun büyük; sorun object'in büyüklüğü değil, her istekte yeniden ayrılması.
• ArrayPool'dan kiralanan buffer'ı geri vermemek ya da verdikten sonra kullanmaya devam etmek; ikincisi başka bir isteğin verisini bozan, bulunması zor bir hata.
• AllocationTick'e dayanan tabloları kesin dağılım sanmak: bu vakada StringBuilder'ı olduğundan 200 kat büyük gösterdi.
• Working set yük sonrası düşmüyor diye leak alarmı vermek; önce GC heap'in ve gen2 sayısının ne yaptığına bak.

Küçük Bir Deneme

★☆☆ Lab'da /diag/gc'yi --memory 512m ile ve memory limiti olmadan başlatılmış iki container'da çağır; GCHeapHardLimit ve totalAvailableMemoryMB'ın nasıl değiştiğine bak.

★★☆ Kendi servisinde en çok allocation yapan endpoint'i --clrevents gc+allocationsampling ile bul. Aynı yükte bir de gc-verbose al ve ilk beş tipin sıralamasının değişip değişmediğini karşılaştır.

★★★ orders-v2.csv'yi context.Response.BodyWriter (PipeWriter) ile GetSpan/Advance kullanacak şekilde yeniden yaz; ArrayPool'u tamamen kaldır. İstek başına allocation'ı, p95'i ve CPU'yu iki sürüm arasında ölç ve farkın nereden geldiğini bir CPU profiliyle açıkla.

Bu yazıda bellek hızla geliyor ve hızla gidiyordu. Bir sonraki yazıda gidemeyen belleğe bakıyoruz: dotnet-gcdump ile iki heap snapshot'ı alıp karşılaştıracak, singleton bir servise abone olup hiç ayrılmayan handler'ları retention path'leriyle bulacak ve düzeltmeyi üçüncü bir snapshot ile kanıtlayacağız.