PerfView ile Derin Analiz: GC Stats, JIT Stats, Grouping/Folding ve İki Trace'i Karşılaştırmak

Sürüm notu: Bu yazıdaki kodlar .NET 10 (container'da runtime 10.0.15) ile derlenip denenmiştir; dotnet-trace 10.0.750501, Microsoft.Diagnostics.Tracing.TraceEvent 4.0.0 ve yük için k6 2.4.0 kullanılmıştır. PerfView 4.0.0 yalnızca Windows'ta çalıştığı için PerfView adımları resmî kullanıcı kılavuzundan ve sürüm notlarından aktarılmıştır.

Önce Tahmin Et

Sitedeki serilerin ortak örnek uygulaması Bookstore (bir online kitapçı) için ekipte bir öneri var: Bookstore.Api'yi ReadyToRun (kodu yayın sırasında önceden makine koduna derleyen yayın seçeneği) ile yayınlayalım, açılışta JIT (Just-In-Time; kodu çalışma anında makine koduna çeviren derleyici) yükü kalksın. Uygulama açılıp ilk isteğe cevap verene kadar 980 method JIT'leniyor. ReadyToRun açıkken bu sayı kaça düşer: 500'e mi, 100'e mi, sıfıra mı? İkinci soru: aynı kodla, aynı yükte iki kez 10 saniyelik allocation trace'i alıp istek başına allocation'ı karşılaştırırsan iki ölçüm arasındaki fark ne kadar olur? Cevaplar yazının JITStats ve CI bölümlerinde; ikisi de PerfView'in arkasındaki kütüphaneyle ölçüldü.

PerfView'i Almak ve Windows'ta Toplamak

PerfView, Microsoft'un açık kaynak ve ücretsiz performans analiz aracı. Kurulumu yok: GitHub'daki microsoft/perfview deposunun Releases sayfasından tek bir PerfView.exe indiriyorsun. Yazım anındaki son sürüm 4.0.0 (Ekim 2026). Bu sürümle birlikte PerfView ve TraceEvent Windows 10 ve üstünü istiyor, 32 bit desteği kaldırıldı; eski bir Windows sunucuda çalışman gerekiyorsa 3.x serisinde kalman gerekiyor. Aynı sürüm notu TraceEvent kütüphanesinin Linux'ta çalışmaya devam ettiğini de söylüyor; bu yazının ikinci yarısı tam olarak buna dayanıyor.

Windows'ta PerfView veriyi ETW (Event Tracing for Windows; işletim sisteminin çekirdek seviyesindeki tracing altyapısı) ile topluyor, bu yüzden yönetici olarak açılması gerekiyor. Kullanıcı kılavuzundaki komut satırı kullanımını Bookstore'a uyarlarsak:

PerfView.exe /AcceptEula /ThreadTime /MaxCollectSec:30 /LogFile=collect.log collect

/MaxCollectSec kaydı süreyle sınırlıyor; vermezsen PerfView durdurulana kadar yazmaya devam ediyor. /ThreadTime context switch event'lerini de açıyor, böylece CPU'da geçen zamanın yanında thread'lerin nerede beklediği de görünüyor. Kılavuz iki seçeneği daha öne çıkarıyor: /DotNetAllocSampled örneklenmiş allocation stack'leri, /GCCollectOnly ise yalnızca GC (garbage collector; kullanılmayan object'leri temizleyen runtime bileşeni) event'leri için. İkincisi saatlerce açık bırakılabilecek kadar küçük dosya üretiyor. ETW makinedeki bütün process'leri ve kernel'i gördüğü için PerfView'in CPU görünümünde native frame'ler de var; serinin 03. yazısında Linux'ta collect-linux ile almaya çalışıp ortam yüzünden alamadığımız bilginin Windows'taki karşılığı bu.

Linux'tan Gelen .nettrace'i Açmak

Bookstore production'da Linux container'ında çalışıyor ve trace'leri orada dotnet-trace ile alıyoruz. Microsoft Learn'deki dotnet-trace sayfası bu .nettrace dosyalarını Windows'a taşıyıp PerfView ya da Visual Studio'da açabileceğini söylüyor. PerfView'de dosyayı sol taraftaki gezginden açıyorsun; altında stack görünümleri ve olay listesi çıkıyor. İki fark var. Birincisi, EventPipe yalnızca managed kodu gördüğü için native frame ve kernel event'i yok. İkincisi, stack'ler CPU örneklerinden değil, 03'te anlattığımız thread time örneklerinden kuruluyor; bekleyen thread'ler de zaman biriktiriyor. Uygulama unhandled exception ile çökerken alınmış, sonu kesik bir trace'i açman gerekirse dotnet-trace dokümanı PerfView'i /ContinueOnError ile başlatmanı öneriyor.

CPU Stacks: By Name, Call Tree, GroupPats ve Fold%

PerfView'in stack penceresinde üç ana sekme var: By Name (her method'un exclusive ve inclusive zamanı, düz liste), Call Tree (kökten aşağı çağrı ağacı) ve Caller-Callee (seçtiğin bir method'u çağıranlar ve onun çağırdıkları). Analize hep By Name ile başlanıyor. Asıl güç ise pencerenin üstündeki metin kutularında:

• GroupPats: frame adlarını bir pattern'e göre gruplar. PAT->GRUP eşleşen her frame'i gruba çevirir, PAT=>GRUP ise gruba hangi method'dan girildiğini de adın yanında tutar (kılavuzda "entry group").
• Fold%: toplamın bu yüzdesinden küçük düğümleri çağıranının içine katar; F7 ile artırıp listeyi sadeleştirirsin.
• FoldPats: adı verilen frame'leri her zaman çağıranına katar; optimize edilemeyecek bir helper'ı listeden çıkarmak için.
• IncPats ve ExcPats: yalnızca belirli bir frame'i içeren (ya da içermeyen) örnekleri bırakır.

PerfView'in varsayılan gruplaması "Just My App": uygulamanın exe'si ile aynı klasör ağacında olmayan her şeyi tek bir OTHER grubuna toplayıp yalnızca senin kodunu ayrıntılı gösteriyor. Kılavuzun sürüm geçmişine göre bu varsayılan dotnet.exe ile başlatılan uygulamalar için kaldırılmış; notta gerekçe olarak faydasından çok zararı olduğu yazıyor. Mantığı da anlaşılır: dotnet.exe'nin klasöründe senin kodun durmuyor, her şey OTHER'a düşer. dotnet Bookstore.Api.dll ile çalışan bir servisin trace'inde gruplamayı kendin seçmen gerekiyor; kılavuzun önerdiği başlangıç "group module entries", yani {%}!=>module $1.

Bu adımların hepsi PerfView'e özel bir sihir değil; PerfView'in kendisi TraceEvent kütüphanesinin üzerine kurulu ve bu filtreler kütüphanede FilterParams adıyla duruyor. Bu yüzden aynı analizi Linux'ta, küçük bir console uygulamasıyla yapabildim. Bookstore.TraceStats'in kalbi şu:

// PerfView'deki stack penceresinin üstündeki metin kutuları
public sealed record StackFilter(string GroupPats, string FoldPercent, string FoldPats, string IncPats, string ExcPats);

public static class CpuStacks
{
    // PerfView'in .nettrace'ten kurduğu "Thread Time" stack'leriyle aynısı
    public static StackSource Load(string path, StackFilter filter)
    {
        TraceLog log = new(TraceLog.CreateFromEventPipeDataFile(path));
        MutableTraceEventStackSource stacks = new(log) { OnlyManagedCodeStacks = true };
        SampleProfilerThreadTimeComputer computer = new(log, new SymbolReader(TextWriter.Null));
        computer.GenerateThreadTimeStacks(stacks);

        // GroupPats, FoldPats, IncPats ve ExcPats kutuları bu FilterParams alanlarına karşılık geliyor
        FilterParams filterParams = new()
        {
            GroupRegExs = filter.GroupPats,
            FoldRegExs = filter.FoldPats,
            IncludeRegExs = filter.IncPats,
            ExcludeRegExs = filter.ExcPats
        };
        return new FilterStackSource(filterParams, stacks, ScalingPolicyKind.ScaleToData);
    }

    public static Dictionary<string, (float Exclusive, float Inclusive)> ByName(StackSource source, StackFilter filter)
    {
        CallTree tree = new(ScalingPolicyKind.ScaleToData) { StackSource = source };
        // Fold%: toplamın bu yüzdesinden küçük düğümler çağıranına katılıyor
        if (float.TryParse(filter.FoldPercent, out float foldPercent) && foldPercent > 0)
            tree.FoldNodesUnder(foldPercent * tree.Root.InclusiveMetric / 100, true);
        return tree.ByIDSortedExclusiveMetric()
            .GroupBy(n => n.Name)
            .ToDictionary(g => g.Key, g => (g.Sum(n => n.ExclusiveMetric), g.Max(n => n.InclusiveMetric)));
    }
}

SampleProfilerThreadTimeComputer, dotnet-trace'in speedscope çıktısındaki CPU_TIME ve UNMANAGED_CODE_TIME sahte frame'lerini de üreten sınıf. Native kodda ya da beklemede geçen örnekleri ExcPats ile atıp CPU_TIME'ı FoldPats ile çağıranına katınca managed kodda geçen zaman kalıyor. Vaka olarak 03'teki arama endpoint'inin bir regresyonunu kurdum: search-regex-only, düzeltilmiş search-v2'nin projection'ı geri alınmış hâli, yani istemciye yine bütün kitap grafiğini dönüyor. İki endpoint'e de k6 ile tam olarak aynı işi verdim: saniyede 300 istek, 10 saniye, 3.000 istek. Test trace'ini modül bazında gruplayınca:

dotnet run -c Release -- cpu search-regex-only.nettrace \
    --inc "module Microsoft.AspNetCore.Server.Kestrel.Core" --exc UNMANAGED_CODE_TIME \
    --foldpats CPU_TIME --group "{%}!->module $1"

 Exc %  Inc %  Name   (total 3,244 ms)
  92.6   99.7  module System.Private.CoreLib
   4.6   10.6  module Bookstore.Api
   1.3   86.5  module System.Text.Json
   1.0   99.7  module Microsoft.AspNetCore.Server.Kestrel.Core
   0.3  100.0  Threads
   0.1    9.3  module System.Linq

Bir ayrıntıya dikkat: IncPats grup adlarına bakıyor, çünkü PerfView'de olduğu gibi gruplama filtrelemeden önce uygulanıyor. Gruplamadan sonra frame'in adı artık module Microsoft.AspNetCore.Server.Kestrel.Core. Tablo, istek zamanının yüzde 86,5'inin System.Text.Json'ın altında geçtiğini, ama exclusive zamanın neredeyse tamamının CoreLib'de olduğunu söylüyor. JSON'un içinde CoreLib'de ne olduğu bir sonraki adımın sorusu.

İki Trace'i Diff'lemek

PerfView'de diff için iki stack penceresini (test ve baseline) aynı filtrelerle açıyor, test penceresinin Diff menüsünden baseline'ı seçiyorsun. Kılavuzun anlattığı algoritma basit: baseline'daki her örneğin metriği negatife çevrilip test örnekleriyle birleştiriliyor, aynı adlı düğümler birbirini götürüyor ve geriye testte fazladan olan zaman kalıyor. Bunun iki şartı var: iki trace aynı işi temsil etmeli (ben bu yüzden istek sayısını sabitledim) ve sembolleri diff'ten önce çözmelisin, diff penceresinde sembol çözme çalışmıyor. By Name görünümünde aynı hesap, isim başına test eksi baseline demek:

dotnet run -c Release -- diff search-v2.nettrace search-regex-only.nettrace \
    --inc "Microsoft.AspNetCore.Server.Kestrel.Core!" --exc UNMANAGED_CODE_TIME \
    --foldpats CPU_TIME --fold 2

baseline 642 ms, test 3,244 ms, diff +2,602 ms
   Exc ms    Inc ms  Name
   +1,983    +1,983  System.Private.CoreLib!System.Threading.Thread.<PollGC>g__PollGCWorker|67_0()
     +166      +166  System.Private.CoreLib!System.Threading.Monitor.Enter_Slowpath()
     -162      -331  System.Linq!System.Linq.Enumerable+IteratorSelectIterator`2[System.__Canon,System.__Canon].ToListNoPresizing()
     +139      +139  Bookstore.Api!Bookstore.Api.Catalog.SearchEndpoints+<>c__DisplayClass1_3.<MapSearchEndpoints>b__8()
     +119      +119  System.Private.CoreLib!System.Buffer.MemmoveInternal()

3.000 istekte 2,6 saniye fazladan zaman, istek başına 0,87 ms. Bunun 2 saniyesi PollGCWorker'da: thread'ler GC için durdurulmayı bekliyor. Yani regresyon serileştirmenin kendisinden çok, 787 KB'lık cevapların ürettiği allocation'ın tetiklediği GC'lerde. Bu, tek bir trace'e bakarak göremeyeceğin bir sonuç; baseline'da da GC beklemesi var ama dörtte biri kadar.

Tablodaki negatif satır da öğretici. ToListNoPresizing baseline'da var, testte yok, çünkü projection kalkınca kod yolu değişti; bu gerçek bir fark. Ama +139 ms'lik Bookstore satırı kısmen sahte: arama lambda'sı iki endpoint'te derleyicinin verdiği farklı adlarla (DisplayClass1_3 ve başka bir sınıf) duruyor ve birbirini götürmüyor. Kılavuz da büyük negatif değerler varken pozitiflere güvenmemeyi söylüyor. Çaresi gruplamak: modül bazında aynı diff'te Bookstore satırı tek bir isim olur ve iki tarafı birbirini götürür.

GCStats ve JITStats

PerfView'in iki hazır raporu stack görünümünden farklı bir soruya cevap veriyor: zaman içinde ne oldu? GCStats, process başına her GC'yi listeleyip heap'in nasıl büyüdüğünü, GC'lerin ne zaman ve hangi nedenle olduğunu, her birinin ne kadar sürdüğünü özetliyor. JITStats ise hangi method'ların JIT'lendiğini, IL (Intermediate Language; C# derleyicisinin ürettiği ara kod) ve native boyutlarını, derlemenin ne kadar sürdüğünü gösteriyor. İkisi de TraceEvent'teki TraceLoadedDotNetRuntime analiz katmanından besleniyor, aynı veriye kodla ulaşmak birkaç satır:

using EventPipeEventSource source = new(path);
source.NeedLoadedDotNetRuntimes();
source.Process();
TraceLoadedDotNetRuntime runtime = source.Processes()
    .Select(p => p.LoadedDotNetRuntime())
    .First(r => r is not null);

List<TraceGC> gcs = runtime.GC.GCs;                   // GCStats'in satırları
List<TraceJittedMethod> methods = runtime.JIT.Methods; // JITStats'in satırları

04'teki CSV (virgülle ayrılmış düz metin) export'unu saniyede 40 istekle 12 saniye gc-collect profile'ıyla kaydedip GCStats özetini çıkardım:

GCs 207, total pause 222.8 ms, 1.8% of 12.1 s
 Gen  Count  Mean pause  Max pause  Promoted MB
   0      6        0.85       1.13         12.7
   1     57        0.92       3.67         11.8
   2    144        1.15       3.87        102.3
Reasons:
    118  gen2 AllocLarge (BackgroundGC)
     56  gen1 AllocSmall (NonConcurrentGC)
     26  gen2 AllocSmall (BackgroundGC)
      5  gen0 AllocSmall (NonConcurrentGC)

Bu tablo counters'ın tek başına veremeyeceği bir şey söylüyor: GC'lerin çoğu gen2 ve 118'inin nedeni AllocLarge, yani LOH'a (Large Object Heap; 85.000 byte ve üstü object'lerin ayrıldığı heap bölgesi) yapılan allocation. 04'te varılan sonuç burada nedeniyle birlikte görünüyor. Gen2'ler background GC olduğu için ortalama pause 1,15 ms'de kalmış; 04'teki 92 istek/sn yükte bu tablo çok daha ağırdı.

JITStats'in klasik kullanımı açılış analizi. dotnet-trace'i -- ile uygulamayı kendisi başlatacak şekilde çalıştırıp JIT ve loader event'lerini verbose seviyede topladım; ASP.NET Core'un Hosting event'leri de ilk cevabın zamanını veriyor:

dotnet-trace collect --providers Microsoft-Windows-DotNETRuntime:0x2000000018:5,Microsoft.AspNetCore.Hosting \
    --duration 00:00:00:08 -o startup.nettrace -- dotnet Bookstore.Api.dll

Aynı ölçümü ReadyToRun ile yayınlanmış image için de tekrarladım (dotnet publish -c Release --ucr -p:PublishReadyToRun=true):

Tahmin sorusunun cevabı: 980'den 928'e. ReadyToRun yalnızca bizim assembly'mizi önceden derledi ve onun 51 method'u listeden çıktı. Geri kalanı zaten framework'ten geliyor: .NET'in kendi kütüphaneleri ReadyToRun olarak dağıtılıyor, ama uygulamanın tiplerine özel generic instantiation'lar ve lambda'lar yine JIT'e kalıyor. Bu uygulamada açılışın 356 ms'sinin yalnızca 53 ms'si JIT; asıl kalem başka yerde (örneğin ilk istekte 20.000 kitabı bellekte kuran CatalogStore; ilk isteğin kendisi 160 ms sürdü). JITStats olmadan bu öneri büyük ihtimalle "açılış hızlandı gibi" diye kabul edilirdi.

TraceEvent ile Kendi Analizin: CI'da Allocation Kapısı

Programatik analizin asıl getirisi tekrar edilebilirlik: aynı soruyu her build'de sorabilirsin. Bookstore.TraceStats'e iki trace'in istek başına allocation'ını karşılaştıran bir komut ekledim. 04'te anlattığımız .NET 10 AllocationSampled event'inden tip başına tahmini byte'ı, Hosting'in Request/Stop event'inden istek sayısını çıkarıyor:

public static AllocationProfile Load(string path)
{
    using EventPipeEventSource source = new(path);
    Dictionary<string, double> bytesByType = [];
    int requests = 0;
    source.Clr.AllocationSampling += e =>
    {
        // runtime'ın randomized allocation sampling tasarımındaki tahmin: boyut / (1 - q^boyut)
        double estimate = e.ObjectSize / (1 - Math.Pow(1 - 1.0 / 102_400, e.ObjectSize));
        bytesByType[e.TypeName] = bytesByType.GetValueOrDefault(e.TypeName) + estimate;
    };
    source.Dynamic.AddCallbackForProviderEvent("Microsoft.AspNetCore.Hosting", "Request/Stop", _ => requests++);
    source.Process();
    return new AllocationProfile(Math.Max(requests, 1), bytesByType);
}

gate komutu ikisini karşılaştırıp istek başına allocation izin verilen yüzdeden fazla artarsa 1 ile çıkıyor; CI'da adımı kırmak için bu yeterli. Trace'ler --clrevents gc+allocationsampling --providers Microsoft.AspNetCore.Hosting ile alındı. Baseline olarak 04'te düzeltilmiş orders-v2.csv'yi, test olarak eski orders.csv'yi verince:

dotnet run -c Release -- gate alloc-orders-v2.nettrace alloc-orders.nettrace --max-growth 10

baseline 88.1 KB/request, test 59,376.3 KB/request, +67298.8%
   23,556.0 KB  System.Char[]
   23,467.6 KB  System.String
   11,735.1 KB  System.Byte[]
FAIL: allocation per request grew more than 10%

Buraya kadar beklenen. Asıl ders, aynı kodu kendisiyle karşılaştırınca çıktı. Tahmin sorusunun ikinci cevabı: orders-v2.csv'den 10'ar saniyelik iki trace aldım, ikisi de 400 istek, ve kapı yüzde 22,1 artış gösterip kırıldı (88,1 KB'a karşı 107,6 KB). Örnekleme ortalama 100 KB'ta bir örnek alıyor; istek başına 90 KB yapan bir endpoint'te 10 saniye, istatistiksel olarak sağlam bir tahmin için az. Aynı ölçümü 30'ar saniyelik (1.200 istek) iki trace'le tekrarlayınca fark yüzde 1,2'ye indi. Böyle bir kapıyı kurmadan önce aynı build'i birkaç kez kendisiyle karşılaştır, gürültünün büyüklüğünü ölç ve eşiği onun üstüne koy; yoksa ekip kırmızı build'lere güvenmemeyi öğrenir.

Ne Zaman PerfView, Ne Zaman IDE Profiler

PerfView'in öğrenme eğrisi dik: arayüzü yoğun, varsayılanları uzmanlara göre ve bir şeyin neden boş göründüğünü anlamak bazen kılavuzda arama yapmayı gerektiriyor. Karşılığında verdiği şey esneklik ve ölçek: production'dan gelen büyük trace'ler, iki trace'in diff'i, GC ve JIT raporları, Windows'ta kernel ve native frame'ler, hepsi ücretsiz ve tek bir exe'de. Kendi kodunu geliştirici makinende profillemek, satıra gitmek, bir database sorgusunu ya da async akışı görmek için Visual Studio veya Rider profiler'ları daha hızlı sonuç veriyor; onlar bir sonraki yazının konusu. Benim kuralım: soru "bu değişiklik neyi yavaşlattı" ya da "production'da ne oldu" ise PerfView veya TraceEvent, soru "bu method neden yavaş" ise IDE.

Üretimde Dikkat

ETW ile toplanan bir PerfView trace'i makinedeki bütün process'leri içeriyor; komut satırları, dosya yolları, başka servislerin method adları dosyanın içinde. Dosyayı paylaşmadan önce bunu düşün ve dump'larla aynı erişim kurallarına tabi tut. /ThreadTime ve allocation seçenekleri dosyayı hızla büyütüyor; kılavuz örneklenmiş allocation'ın production'da bırakılabilecek kadar düşük maliyetli olduğunu söylese de, kendi servisinde 01'deki gibi araçlı ve araçsız bir A/B ölçümü yapmadan buna güvenme.

Programatik analizde de dikkat edilecek iki şey var. TraceEvent büyük bir .nettrace'i önce bir ETLX (TraceEvent'in indekslenmiş trace formatı) dosyasına çeviriyor; CI ajanında disk ve süre bütçesini buna göre ayır. Kapı için alınan trace'lerin yükü sabit olmalı: sabit istek hızı, aynı ısınma, aynı veri. Benim örneğimde istek sayısını Hosting event'lerinden saydım; böylece trace süresi biraz kaysa da istek başına değer bozulmuyor.

Sık Düşülen Tuzaklar

• Farklı miktarda iş içeren iki trace'i diff'lemek: test trace'i iki kat istek aldıysa her satır "regresyon" görünür. İstek sayısını sabitle ya da istek başına normalize et.
• Diff'te büyük negatif satırları görmezden gelmek: derleyicinin ürettiği lambda adları gibi değişen isimler birbirini götürmez; önce grupla.
• IncPats'i gruplanmış isimlerden önce düşünmek: gruplama filtrelemeden önce uygulandığı için pattern grup adına göre yazılmalı.
• Thread time'daki PollGC ya da semaphore beklemesini "CPU'yu yiyen kod" diye okumak; bunlar bekleme.
• JITStats'e bakmadan ReadyToRun'dan büyük açılış kazancı beklemek; framework zaten önceden derlenmiş.
• Örneklemeye dayalı bir CI kapısını gürültüsünü ölçmeden açmak.

Küçük Bir Deneme

★☆☆ Windows'taysan 03'teki search trace'ini PerfView'de aç; By Name'de GroupPats'i önce boşalt, sonra {%}!=>module $1 yap ve Fold%'yi F7 ile artırarak listenin nasıl sadeleştiğine bak. Linux'taysan aynı adımları Bookstore.TraceStats'in cpu komutuyla dene.

★★☆ Bookstore.TraceStats'e gc raporunun yanında GC pause'larının p50/p95/p99'unu yazan bir satır ekle ve 04'teki orders.csv ile orders-v2.csv'nin GCStats'ini karşılaştır.

★★★ gate komutunu aynı build'den alınmış N trace'in ortalamasına ve standart sapmasına göre eşik koyacak şekilde genişlet. Kaç saniyelik ve kaç trace'lik bir ölçümün yüzde 5'lik bir regresyonu güvenilir biçimde yakaladığını bul.

PerfView ve TraceEvent sana trace'in her ayrıntısını veriyor, ama bedeli zaman. Bir sonraki yazıda daha hızlı sonuç veren tarafa geçiyoruz: Visual Studio 2026 ve Rider profiler'ları; CPU Usage, .NET Object Allocation, Instrumentation, .NET Async ve Database araçlarıyla Bookstore'un sipariş listesindeki bir Entity Framework Core (EF Core) N+1 sorgusunu bulup düzelteceğiz.