CPU Profiling: dotnet-trace ile Flame Graph Okumak, Sampled Thread Time ve Linux'ta collect-linux

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, örnek sayımı için Microsoft.Diagnostics.Tracing.TraceEvent 3.2.8 kullanılmıştır.

Önce Tahmin Et

Bir önceki yazıda metric'ler, Bookstore'da JIT'in (Just-In-Time; kodu çalışma anında makine koduna çeviren derleyici) ısınmış bir serviste saniyede yüzlerce method derlediğini gösterdi. Şüpheli endpoint belli: /api/books/search. Yük altında 15 saniyelik bir trace alıp dotnet-trace report ile en çok zaman alan method'ları listeliyorsun. Listenin ilk sıralarında ne görmeyi beklersin: Regex, JSON serileştirme, yoksa bambaşka bir şey? Ve şunu da düşün: bu endpoint'in throughput'unu 23 katına çıkaran düzeltme hangisi olur, CPU'yu yiyen kodu düzeltmek mi, başka bir şey mi?

Varsayılan Profile'lar: Örneklenen Şey CPU Değil, Duvar Saati

dotnet-trace'i profile vermeden çalıştırınca iki profile açılıyor: dotnet-common (GC yani garbage collector, JIT, assembly yükleme, exception gibi hafif runtime event'leri) ve dotnet-sampled-thread-time. İkincisi işin kalbi: runtime belirli aralıklarla bütün managed thread'leri durdurup her birinin stack'ini kaydediyor. Önemli ayrıntı şu: thread CPU'da çalışıyor olsun ya da bir lock'ta, semaphore'da, I/O'da beklesin, örnek alınıyor. Yani bu bir CPU profili değil, thread'lerin zamanını nerede geçirdiğinin profili.

Eski sürümlerde bu işi yapan profile'ın adı cpu-sampling'di ve tam da bu yüzden collect komutundan kaldırıldı: CPU kullanmayan thread'leri de saydığı için adı yanıltıcıydı. Eski davranışa en yakın karşılık --profile dotnet-sampled-thread-time,dotnet-common. cpu-sampling adı şimdi yalnızca collect-linux'ta var ve orada gerçekten kernel'in CPU örneklemesi demek.

Örnekleme sıklığı için iki farklı sayı göreceksin: Microsoft Learn'deki dotnet-trace sayfası yaklaşık 1000 Hz diyor, aracın kendi list-profiles çıktısı yaklaşık 100 Hz. Ben trace'teki örnek event'lerini TraceEvent ile saydım: bu container'da boşta thread başına saniyede 499, yük altında 403 örnek çıktı. Kesin sıklığı varsayma; analizde mutlak süreye değil, yüzdelere bak. Sıklığı değiştirmek gerekirse .NET 10.0.10 ve sonrasında DOTNET_EventPipeThreadSamplingRate ortam değişkeni (milisaniye) var; process genelinde geçerli.

Vaka: Arama Endpoint'i

Lab'daki arama endpoint'i, gerçek projelerde gördüğüm iki hatayı birleştiriyor:

// yavaş sürüm: her istekte derlenen bir Regex ve cevapta bütün entity grafiği
app.MapGet("/api/books/search", (string q, CatalogStore store) =>
{
    Regex separator = new(@"[^\p{L}\p{N}]+", RegexOptions.Compiled);
    string[] terms = separator.Split(q).Where(t => t.Length > 0).ToArray();

    List<Book> hits = store.Books
        .Where(b => terms.All(t => b.Title.Contains(t, StringComparison.OrdinalIgnoreCase)))
        .Take(50)
        .ToList();

    return Results.Ok(hits);
});

Book; yazarını (2.000 karakterlik biyografisiyle) ve 30 yorumunu taşıyan bir record. Arayüz yalnızca başlık, yazar adı ve fiyat gösteriyor ama cevap 50 kitabın her şeyini içeriyor: 787 KB. RegexOptions.Compiled ise pattern'i IL'e (Intermediate Language; C# derleyicisinin ürettiği ara kod) derleyip çalışma anında yeni method'lar üretiyor; bu bir kez yapıldığında hızlı, her istekte yapıldığında felaket.

20 sanal kullanıcıyla k6 yükü altındayken trace aldım:

docker exec profseries-api dotnet-trace collect -p 1 --duration 00:00:00:15 -o /tmp/search-before.nettrace
docker cp profseries-api:/tmp/search-before.nettrace .
dotnet-trace report search-before.nettrace topN -n 12 --inclusive

Top 12 Functions (Inclusive)                                                  Inclusive           Exclusive
1.  (Non-Activities)                                                          100%                0%
2.  Threads                                                                   100%                0%
3.  Thread.StartCallback()                                                    80.97%              0%
4.  PortableThreadPool+WorkerThread.WorkerThreadStart()                       36.51%              0.02%
5.  LowLevelLifoSemaphore.Wait(int32,bool)                                    19.16%              0.07%
6.  WaitHandle.WaitOneNoCheck(int32,bool,class System.Object,value class W    19.06%              19.06%
7.  LowLevelLifoSemaphore.WaitForSignal(int32)                                18.97%              18.93%
8.  ThreadPoolWorkQueue.Dispatch()                                            17.31%              0%
9.  ExecutionContext.RunFromThreadPoolDispatchLoop(class System.Threading.    14.29%              0%
10. Monitor.Wait(class System.Object,int32)                                   12.7%               12.7%
11. ManualResetEventSlim.Wait(int32,value class System.Threading.Cancellat    12.7%               6.35%
12. Missing Symbol                                                            12.24%              12.18%

Tahmin sorusunun ilk cevabı: listenin tepesinde ne Regex var ne JSON. İlk sıraları bekleyen thread'ler kaplıyor; thread pool'un iş bekleyen worker'ları (LowLevelLifoSemaphore.WaitForSignal), timer ve log thread'leri (Monitor.Wait). Duvar saati örneklemesinde boşta bekleyen her thread de zaman biriktirir. Bu liste sana "bu process'in thread'leri zamanının beşte birini iş bekleyerek geçiriyor" diyor, "CPU'yu ne yiyor" sorusuna cevap vermiyor.

Flame Graph Okumak: speedscope ve Chromium

Asıl analiz için trace'i görsel bir araçta açmak gerekiyor. Windows'ta .nettrace'i Visual Studio ya da PerfView doğrudan açıyor (06 ve 07). Platformdan bağımsız yol, trace'i speedscope ya da Chromium formatına çevirmek:

dotnet-trace convert search-before.nettrace --format Speedscope -o search-before
dotnet-trace convert search-before.nettrace --format Chromium -o search-before

Processing trace data file 'search-before.nettrace' to create a new Speedscope file 'search-before.speedscope.json'.
Conversion complete

search-before.speedscope.json'ı tarayıcıda speedscope.app'e, .chromium.json'ı Chrome DevTools'un Performance paneline yüklüyorsun. Dönüşüm geri alınamıyor; orijinal .nettrace'i sakla. speedscope'ta her thread ayrı bir profile; "Left Heavy" görünümü aynı stack'leri birleştirip en geniş olanı sola diziyor. Flame graph'ı okurken üç kural yeterli: genişlik o frame'in toplam zamandaki payı, dikey eksen çağrı derinliği (alttaki çağırır, üstteki çağrılır), renkler anlamsız. dotnet-trace'in speedscope çıktısı her stack'in en üstüne iki sahte frame koyuyor: CPU_TIME (thread managed kod çalıştırıyordu) ve UNMANAGED_CODE_TIME (native kodda ya da beklemede). Bekleyen thread'leri ayıklamak için bakacağın yer bu ikisi.

Inclusive ve exclusive farkı da burada önem kazanıyor. Inclusive zaman, method'un ve çağırdığı her şeyin toplamı; exclusive zaman, yalnızca method'un kendi gövdesinde geçen süre. dotnet-trace report varsayılan olarak exclusive'e göre sıralıyor, --inclusive ile çağrı ağacında yukarıdaki method'ları görüyorsun. Handler'ın inclusive'i yüksek, exclusive'i düşükse zaman onun çağırdığı bir şeyde demektir.

İstek thread'lerine odaklanınca tablo değişti. Kestrel'in HttpProtocol.ProcessRequests frame'i altındaki meşgul zamanı (beklemeyen örnekleri) bileşenlere ayırdım:

İstek zamanının yüzde 78,9'u Regex'te. İlginç olan nerede olduğu: Regex'in constructor'ı yalnızca 0,7 saniye; geri kalan 18 saniye dynamicClass.Regex575014_Scan gibi isimleri olan derlenmiş method'larda. Her istek yeni bir Regex derlediği için her istekte yeni bir Scan method'u doğuyor ve ilk çağrısında JIT'e gidiyor. 15 saniyelik trace'te birbirinden farklı 6.469 RegexNNN_Scan adı saydım. topN'in bunu hiç göstermemesinin nedeni de bu: süre binlerce farklı isme bölündüğü için hiçbiri tek başına listeye giremiyor. Flame graph'ta ise handler'ın üstünde ince çizgilerden oluşan geniş bir tarak olarak hemen göze çarpıyor.

Bir de istek dışında bir sürpriz var: finalizer thread'i 15 saniyenin 13,8'ini DynamicResolver+DestroyScout.Finalize()'da, yani atılan dynamic method'ları temizleyerek geçirmiş. Tek bir thread'in neredeyse tamamen bu işe gitmesi, temizlik hızı üretim hızına yetişemezse belleğin de büyüyeceği anlamına geliyor.

Düzeltme: [GeneratedRegex] ve Projection

public sealed record BookSearchResult(int Id, string Title, string AuthorName, decimal Price);

public static partial class SearchEndpoints
{
    [GeneratedRegex(@"[^\p{L}\p{N}]+")]
    private static partial Regex TermSeparator();

    public static void MapSearchEndpoints(this IEndpointRouteBuilder app)
    {
        // düzeltilmiş sürüm: derleme anında üretilen Regex ve yalnızca istemcinin ihtiyacı olan alanlar
        app.MapGet("/api/books/search-v2", (string q, CatalogStore store) =>
        {
            string[] terms = TermSeparator().Split(q).Where(t => t.Length > 0).ToArray();

            List<BookSearchResult> hits = store.Books
                .Where(b => terms.All(t => b.Title.Contains(t, StringComparison.OrdinalIgnoreCase)))
                .Take(50)
                .Select(b => new BookSearchResult(b.Id, b.Title, b.Author.Name, b.Price))
                .ToList();

            return Results.Ok(hits);
        });
    }
}

[GeneratedRegex] pattern'i build sırasında C# koduna çeviriyor; çalışma anında derleme ya da IL üretimi yok ve trace'te method'un gerçek bir adı oluyor (RegexGenerator_g...TermSeparator). static readonly Regex alanı da işi görürdü; önemli olan Regex'i bir kez oluşturmak. Projection ise cevabı 787 KB'tan 4 KB'a indiriyor. İki düzeltmenin etkisini ayırmak için yalnızca Regex'i düzelten ara bir endpoint daha ekledim ve üç sürümü aynı yükle (20 sanal kullanıcı, 20 saniye) ölçtüm; CPU ve JIT değerleri aynı anda alınan dotnet-counters kaydından:

Tahmin sorusunun ikinci cevabı burada. Profilin gösterdiği düzeltme (Regex) istek başına CPU'yu yarıya indirdi ama throughput'u yalnızca yüzde 47 artırdı. 23 katlık sıçramayı projection getirdi. Nedeni şu: yavaş sürümde container'ın 4 CPU'sundan yalnızca 1,7'si kullanılıyordu; darboğaz CPU değil, saniyede 0,7-1,1 GB'lık cevap trafiğiydi. Sampled thread time profili bunu göremez, çünkü async bir yazma işleminde soket'in boşalmasını bekleyen istek hiçbir thread'i meşgul etmiyor; örneklenecek bir stack yok. Flame graph sana CPU'nun nereye gittiğini doğru söyler, ama "neden yavaş" sorusunun tamamı orada olmayabilir. Bu yüzden önce/sonra karşılaştırmasını her zaman uçtan uca bir ölçümle (p95, throughput) ve kaynak kullanımıyla birlikte yap.

Düzeltilmiş sürümün profilinde Regex'ten eser kalmadı (2 ms); istek zamanının yüzde 69'u 20.000 kitabı baştan sona tarayan Where/All/Contains'te, yüzde 21'i JSON'da. Sıradaki iyileştirme bir arama index'i olurdu, ama 0,07 ms'lik bir istek için buna ancak yük gerçekten gerektirirse girerim.

Linux'ta collect-linux

.NET 10 ile gelen collect-linux, EventPipe yerine kernel'in perf_events ve user_events altyapısını kullanıyor. Kazancı: native frame'ler (JIT'in kendisi, GC, native kütüphaneler) stack'lerde görünüyor, gerçek CPU örneklemesi (cpu-sampling) ve context switch'ler (thread-time) alınabiliyor ve makinedeki bütün process'ler aynı anda izlenebiliyor. Yukarıdaki vakada UNMANAGED_CODE_TIME olarak görünen JIT süresinin içini ancak bununla açabilirsin. Şartları ağır: kernel 6.4+ ve CONFIG_USER_EVENTS, mount edilmiş tracefs, root (CAP_PERFMON ya da CAP_SYS_ADMIN), .NET 10 runtime, glibc 2.27+ (Alpine 3.22 hariç). Native frame'lerin adları için runtime'ın sembollerini dotnet-symbol ile indirip kütüphanelerin yanına koymak gerekiyor.

Önce process'in bu modu destekleyip desteklemediğine root gerektirmeyen --probe ile bakılabiliyor:

docker exec profseries-api dotnet-trace collect-linux --probe

Probing .NET processes for support of the EventPipe UserEvents IPC command used by collect-linux. Requires runtime '10.0.0' or later.
.NET processes that support the command:
1 dotnet

.NET processes that do NOT support the command:

Process destekliyor ama ortam desteklemeyebilir. Lab container'ında root olarak denediğimde araç önce tracefs'in mount edilmemiş olduğunu söyledi; privileged bir container'da tracefs'i mount edip tekrar denediğimde ikinci engele takıldı:

Error: Tracefs is not accessible: It appears tracefs is not mounted. You can mount it by running mount -t tracefs nodev /sys/kernel/tracing.

Error: User events are not accessible.

Bu ortamın kernel'i 6.12 ama CONFIG_USER_EVENTS açık değil. Bir Linux sunucusunda denemeden önce zgrep CONFIG_USER_EVENTS /proc/config.gz ya da /sys/kernel/tracing/user_events_data dosyasının varlığıyla kontrol et. Container'da çalışıyorsan bu iş pod'un değil, node'un kernel'inin ve verilen yetkilerin sorusu; yani çoğu zaman platform ekibiyle konuşman gerekecek. Windows'ta bunun karşılığı zaten var: ETW (Event Tracing for Windows; Windows'un kernel seviyesindeki tracing altyapısı) üzerinden çalışan PerfView ve Visual Studio native frame'leri de gösteriyor.

Üretimde Dikkat

Production'da CPU trace'i kısa tut: 10-30 saniye, sorunun yaşandığı pencerede. Sorun aralıklıysa trace'i sürekli açık bırakmak yerine bir tetikleyiciye bağla; dotnet-monitor'ın collection rule'ları bunun için (08). Trace'in sonunda runtime "rundown" denen bir aşamada yüklü method'ların adlarını ve adreslerini gönderiyor; büyük bir uygulamada durdurma birkaç saniyeden dakikalara uzayabiliyor, process'i bu sırada öldürme. Trace dosyası method adları ve stack'ler taşıyor, gizli bilgi taşıma ihtimali dump'tan düşük ama sıfır değil; özellikle --providers ile payload'lı event'ler açtıysan.

Ölçtüğün şeyin production'daki sorun olduğundan emin ol. Burada k6 ile 20 kullanıcı üretilen yükte darboğaz ağ trafiğiydi; production'da aynı endpoint'i belki saniyede 50 istek çağırıyor ve asıl derdin GC ya da finalizer kuyruğu. Profil, hangi yükte alındıysa onu anlatır.

Sık Düşülen Tuzaklar

• Debug build'i profillemek: inlining ve optimizasyonlar kapalı, sıcak noktalar değişiyor. Her zaman -c Release.
• Uygulama açılır açılmaz kısa bir trace almak: tiered compilation yüzünden ilk saniyelerde method'lar önce hızlı ama optimize edilmemiş hâlde derleniyor, sonra yeniden derleniyor; profil JIT gürültüsüyle dolar. Isınma için birkaç bin istek gönder, sonra kaydet.
• Sampled thread time'ı CPU profili sanmak ve listenin başındaki bekleme method'larını "sıcak nokta" diye okumak.
• topN'e güvenip flame graph'a bakmamak: çalışma anında üretilen method'lar binlerce isme bölünüp listeden kaybolur.
• Uygulama unhandled exception ile çökerken trace almak: rundown gelmediği için stack'ler çözülmeyebilir; PerfView bu durumda /ContinueOnError ile açabiliyor, ama çökme için doğru araç dump.
• Yalnızca profilin gösterdiğini düzeltip uçtan uca ölçmemek: bu vakada CPU yarıya indi, kullanıcının gördüğü süre çok az değişti.

Küçük Bir Deneme

★☆☆ Lab'ın search endpoint'ine yük ver, trace al ve speedscope'ta aç. "Left Heavy" görünümünde handler'ın üstündeki tarak şeklini bul; birkaç RegexNNN_Scan adının birbirinden farklı olduğunu kendi gözünle gör.

★★☆ RegexOptions.Compiled'ı kaldırıp new Regex(...)'i yine her istekte oluşturan bir sürüm yaz. Interpreter modunda her istekte Regex kurmanın maliyetini dotnet.jit.compiled_methods ve istek başına CPU ile ölç; Compiled'ın hangi durumda zarar, hangi durumda kazanç olduğunu not et.

★★★ search-v2'deki doğrusal taramayı başlık kelimelerinden kurulan bir Dictionary<string, List<Book>> index'iyle değiştir. Önce/sonra flame graph'ını ve p95'i karşılaştır; index'in kurulma süresini ve bellekteki maliyetini de hesaba kat.

CPU tarafında finalizer thread'inin ne kadar meşgul olduğunu gördük; bir sonraki yazıda belleğin öbür yüzüne geçiyoruz: allocation'ları gc-verbose ve allocation sampling ile stack'e bağlayacak, LOH'u (Large Object Heap; büyük object'lerin tutulduğu heap bölgesi) dolduran bir CSV (virgülle ayrılmış düz metin) export'unu streaming ve ArrayPool<T> ile düzeltecek, Server GC ve DATAS (Dynamic Adaptation To Application Sizes; heap'i uygulamanın ihtiyacına göre büyütüp küçülten GC modu) ayarlarına bakacağız.