Hang ve Yavaşlık Teşhisi: dotnet-stack, dotnet-trace ve Thread Pool Starvation

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

Önce Tahmin Et

Sipariş özeti endpoint'i stok servisine bir HTTP (Hypertext Transfer Protocol) çağrısı yapıyor; stok servisi her isteğe 200 ms'de cevap veriyor. Endpoint bu çağrının sonucunu await yerine .Result ile alıyor. Tek istek attığında cevap 0,37 saniyede geliyor, sorun yok gibi. Servis 2 CPU'luk (Central Processing Unit) bir container'da çalışıyor ve aynı anda 200 istek geliyor. Bu 200 isteğin ortanca (p50) cevap süresi kaç olur: 0,2 saniye mi, 2 saniye mi, 20 saniye mi? Aynı yük altında await kullanan sürümü ne yapar? Gerçek ölçümler aşağıda; ilk cevap üç seçeneğin de dışında.

"Uygulama Cevap Vermiyor" Ne Demek?

Bu şikâyetin arkasında üç ayrı durum olabilir ve araç seçimi buna göre değişir. Process tamamen donmuşsa (hang) thread'ler bir yerde bekliyordur: lock, I/O (Input/Output), başka bir thread. Process çalışıyor ama yavaşsa, ya CPU tükenmiştir ya da iş bekleyen thread yüzünden ilerlemiyordur. Üçüncüsü, process hiç değilken uygulamanın bir bağımlılığı yavaştır; o zaman sorun bu process'te bile değildir.

Benim sıram şöyle: önce birkaç saniyelik metrik (CPU yüzde kaç, thread pool'da kaç thread var, queue'da kaç iş bekliyor), sonra bütün thread'lerin anlık stack'i (dotnet-stack), en son da süresi sınırlı kısa bir trace (dotnet-trace). Dump (09) da bir seçenek, ama yüzlerce MB'lık bir dosya ve kısa bir donma demek; dotnet-stack aynı soruya saniyeler içinde, birkaç KB ile cevap verir. Derin CPU ve allocation analizi bu yazının konusu değil; o iş ilerideki .NET'te Profiling ve Diagnostics serisinde.

Vaka: Sync-over-Async ile Kendini Tıkayan Servis

Kod, sync-over-async'in en yaygın hâli. Stok servisini ayrı bir container'da çalıştırdım; sipariş servisi --cpus 2 ile kısıtlı:

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Services.AddHttpClient<InventoryClient>(client =>
    client.BaseAddress = new Uri(builder.Configuration["Inventory:BaseUrl"]!));

WebApplication app = builder.Build();

// yavaş bağımlılık: yaklaşık 200 ms'de cevap veren stok endpoint'i
app.MapGet("/inventory/{bookId:int}", async (int bookId) =>
{
    await Task.Delay(200);
    return Results.Ok(new StockInfo(bookId, 7));
});

// sync-over-async: çağrı boyunca bir thread pool thread'ini bloklar
app.MapGet("/orders/{id:int}/summary", (int id, InventoryClient inventory) =>
{
    StockInfo stock = inventory.GetStockAsync(id).Result;
    return Results.Ok(new { id, stock.Available });
});

// düzeltme: çağrı sürerken thread havuza geri döner
app.MapGet("/orders/{id:int}/summary-async", async (int id, InventoryClient inventory) =>
{
    StockInfo stock = await inventory.GetStockAsync(id);
    return Results.Ok(new { id, stock.Available });
});

app.Run();

public sealed record StockInfo(int BookId, int Available);

public sealed class InventoryClient(HttpClient httpClient)
{
    public async Task<StockInfo> GetStockAsync(int bookId)
    {
        StockInfo? stock = await httpClient.GetFromJsonAsync<StockInfo>($"/inventory/{bookId}");
        return stock!;
    }
}

Yükü, HttpClient ile 200 eşzamanlı istek atan, 40 saniye boyunca bitirdikçe yenisini gönderen küçük bir C# konsol uygulamasıyla verdim. Bloklayan endpoint'in sonucu:

$ dotnet loadgen/bin/Release/net10.0/LoadGen.dll http://localhost:5420/orders/1/summary 200 40
requests=200 errors=0 rps=4.2
p50=46993ms p95=47198ms p99=47198ms max=47198ms

200 isteğin ortancası 47 saniye. 40 saniyelik testte her worker yalnızca bir istek bitirebildi. Hiç hata yok, hiç timeout yok; servis "çalışıyor" ama 47 saniye boyunca neredeyse hiçbir şey yapmıyor. Sağlık kontrolü (health check) aynı thread pool'u kullanıyorsa o da bu sürede cevap veremez ve orchestrator pod'u yeniden başlatır; sorun kendi kendine "düzelmiş" gibi görünür. Teoriyi C# Asenkron serisinin "C# Deadlock, SynchronizationContext ve ConfigureAwait" yazısı anlatıyor. Burada teşhise odaklanıyoruz: bunu bilmeden, yalnızca çalışan process'e bakarak nasıl bulurdun?

dotnet-counters ile Hızlı Bakış

İlk bakış metriklere. Araçları uygulamanın image'ına, 09'daki gibi multi-stage build ile /tools klasörüne kurdum ve docker exec ile çalıştırdım:

docker exec debugwork-app-10 dotnet-counters collect -p 7 \
  --counters 'System.Runtime[dotnet.thread_pool.thread.count,dotnet.thread_pool.queue.length,dotnet.thread_pool.work_item.count]' \
  --refresh-interval 1 --duration 00:00:00:55 -o /tmp/bad.csv

CSV (Comma-Separated Values) dosyasını açınca ilk sürpriz: thread sayısı ve queue uzunluğu gibi "anlık değer" metrikleri bu sürümde Rate tipiyle, saniyelik değişim olarak yazılmış. Queue uzunluğu sütununda -5, -4 gibi negatif değerler görünce fark ettim:

Timestamp,Provider,Counter Name,Counter Type,Mean/Increment
11/08/2026 09:08:00,System.Runtime,dotnet.thread_pool.thread.count ({thread} / 1 sec),Rate,10
11/08/2026 09:08:00,System.Runtime,dotnet.thread_pool.queue.length ({work_item} / 1 sec),Rate,146
11/08/2026 09:08:00,System.Runtime,dotnet.thread_pool.work_item.count ({work_item} / 1 sec),Rate,25
11/08/2026 09:08:01,System.Runtime,dotnet.thread_pool.thread.count ({thread} / 1 sec),Rate,5
11/08/2026 09:08:01,System.Runtime,dotnet.thread_pool.queue.length ({work_item} / 1 sec),Rate,-5

Değişimleri toplayınca (küçük bir Python script'iyle) mutlak değerler çıkıyor. Yükün başladığı andan itibaren, birkaç saniyede bir:

Thread pool starvation'ın imzası tam bu: thread sayısı sabit bir hızla (burada saniyede yaklaşık 4) tırmanıyor, queue yavaş yavaş eriyor, saniyede biten iş sayısı ise yerde. Başlangıçtaki 2 tesadüf değil: thread pool'un varsayılan minimumu işlemci sayısı kadar ve --cpus 2 ile runtime 2 işlemci görüyor. Minimumun üstündeki her yeni thread'i runtime ölçerek, kademeli ekliyor. 200 bloklanmış istek için yaklaşık 200 thread gerektiğinden bekleme 47 saniye sürdü. Microsoft Learn'deki thread pool starvation öğreticisi de aynı iki sinyali veriyor: thread sayısının yavaş ve sürekli artışı ve yüzde 100'ün çok altında kalan CPU.

dotnet-stack: Bütün Thread'lerin Anlık Stack'i

Metrikler "thread'ler bir şey bekliyor" diyor; neyi beklediklerini stack söyler. dotnet-stack, EventPipe üzerinden bütün thread'lerin managed stack'ini bir kez alıp basar. Yük başladıktan 12 saniye sonra:

docker exec debugwork-app-10 dotnet-stack report -p 7 > stack-bad.txt
grep -c '^Thread (' stack-bad.txt
grep -c 'b__0_2(int32,class InventoryClient)' stack-bad.txt

69
60

69 thread'in 60'ı aynı lambda'nın içinde. Birinin stack'i (Kestrel ve thread pool frame'lerinin ortasını kestim):

Thread (0x45):
  [Native Frames]
  System.Private.CoreLib!System.Threading.Monitor.Wait(class System.Object,int32)
  System.Private.CoreLib!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib!System.Threading.Tasks.Task.InternalWait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib!System.Threading.Tasks.Task`1[System.__Canon].GetResultCore(bool)
  Bookstore.Api!Program+<>c.<<Main>$>b__0_2(int32,class InventoryClient)
  Anonymously Hosted DynamicMethods Assembly!dynamicClass.lambda_method2(pMT: 0xffff48e58680,class System.Object,pMT: 0xffff47e5e3a0)
  System.Private.CoreLib!System.Threading.ThreadPoolWorkQueue.Dispatch()
  System.Private.CoreLib!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()

Aşağıdan yukarı oku: en altta WorkerThreadStart, yani bu bir thread pool thread'i. Ortada bizim kodumuz, b__0_2 (Program.cs'teki üçüncü lambda, /summary handler'ı). En üstte GetResultCore ve ManualResetEventSlim.Wait: .Result thread'i bir event üzerinde uyutuyor. Bir thread pool thread'inin stack'inin tepesinde Wait görmek, sync-over-async için en net kanıttır. dotnet-stack'in avantajı hızı: process'i durdurmadan, dosya taşımadan, birkaç saniyede. Dezavantajı tek bir an olması; sorun ara sıra oluyorsa o anı yakalayamayabilirsin.

dotnet-trace collect: Kısa ve Sınırlı Bir Kayıt

Ara sıra olan bloklamalar için zaman içinde kayıt gerekir. Profil vermeden çalıştırınca dotnet-trace iki varsayılan profil açıyor:

$ dotnet-trace collect -p 7 --duration 00:00:00:05 -o /tmp/sampled.nettrace
No profile or providers specified, defaulting to trace profiles 'dotnet-common' + 'dotnet-sampled-thread-time'.
Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x000000100003801D  Informational(4)    --profile
Microsoft-DotNETCore-SampleProfiler     0x0000F00000000000  Informational(4)    --profile
Process        : /usr/share/dotnet/dotnet
Output File    : /tmp/sampled.nettrace
Trace Duration : 00:00:00:05
Stopping the trace. This may take several minutes depending on the application being traced.
Trace completed.

dotnet-sampled-thread-time, dokümana göre thread stack'lerini yaklaşık 1000 Hz'de örnekler; CPU kullanmayan, bekleyen thread'ler de örneklenir. Bu yüzden bekleme teşhisi için iyi. Windows'ta PerfView ya da Visual Studio ile açılır; Linux ve macOS'ta dotnet-trace report hızlı bir özet verir. Dosyayı Mac'e kopyalayıp yerel araçla baktım:

$ dotnet tool run dotnet-trace report sampled.nettrace topN -n 20 --inclusive | grep -E "Top|Program|GetResultCore|Monitor.Wait"
Top 20 Functions (Inclusive)                                                  Inclusive           Exclusive
11. Api!Program+<>c.<<Main>$>b__0_2(int32,class InventoryClient)              87.08%              0%
12. __Canon].GetResultCore(bool)                                              87.07%              0%
18. Monitor.Wait(class System.Object,int32)                                   40.39%              40.39%

Örneklerin yüzde 87'sinde stack'te bizim handler'ımız ve GetResultCore var. Thread'ler zamanın neredeyse tamamını orada bekleyerek geçiriyor.

Daha hedefli bir kanıt için .NET 9 ile gelen WaitHandleWait event'leri var: bir thread Task.Result, Task.Wait, lock, ManualResetEventSlim.Wait gibi bir yerde bloklandığında yayınlanır. Yalnızca bu event'leri açan 10 saniyelik bir trace:

docker exec debugwork-app-10 dotnet-trace collect -p 7 \
  --clrevents waithandle --clreventlevel verbose --duration 00:00:00:10 -o /tmp/bad.nettrace

Doküman bu dosyayı PerfView ya da topluluğun yazdığı .NET Events Viewer ile açmayı öneriyor. Bu makinede Windows yok; ben event'leri TraceEvent kütüphanesiyle kendim saydım. Her bekleme event'ini, stack'inde bizim assembly'mizden bir frame varsa ona, yoksa thread'in giriş noktasına yazan kısa bir konsol uygulaması:

using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Etlx;

string etlxPath = TraceLog.CreateFromEventPipeDataFile(args[0]);
using TraceLog log = new(etlxPath);

Dictionary<string, int> waitsByOrigin = [];
int total = 0;

foreach (TraceEvent e in log.Events.Where(e => e.EventName == "WaitHandleWait/Start"))
{
    total++;
    string origin = FindOrigin(e.CallStack());
    waitsByOrigin[origin] = waitsByOrigin.GetValueOrDefault(origin) + 1;
}

Console.WriteLine($"WaitHandleWait/Start events: {total}");
foreach ((string origin, int count) in waitsByOrigin.OrderByDescending(p => p.Value))
{
    Console.WriteLine($"{count,5}  {origin}");
}

static string FindOrigin(TraceCallStack? stack)
{
    string entry = "(no stack)";
    for (TraceCallStack? frame = stack; frame is not null; frame = frame.Caller)
    {
        string method = frame.CodeAddress.FullMethodName;
        // bizim koddan bir frame varsa beklemeyi ona yaz
        if (frame.CodeAddress.ModuleName == "Bookstore.Api")
        {
            return method;
        }

        // yoksa stack'in en dibindeki, thread'i başlatan method'u tut
        if (!method.StartsWith("System.Threading.Thread.StartCallback", StringComparison.Ordinal))
        {
            entry = method;
        }
    }

    return $"[thread entry] {entry}";
}

WaitHandleWait/Start events: 175
   57  [thread entry] System.Threading.PortableThreadPool+GateThread.GateThreadStart()
   39  Program+<>c.<<Main>$>b__0_2(int32,class InventoryClient)
   39  [thread entry] Microsoft.Extensions.Logging.Console.ConsoleLoggerProcessor.ProcessLogQueue()
   20  [thread entry] System.Diagnostics.Tracing.CounterGroup.PollForValues()
   10  [thread entry] Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.Heartbeat.TimerLoop()
   10  [thread entry] System.Diagnostics.Metrics.AggregationManager.CollectWorker()

İki ayrıntı önemli. Birincisi, bekleme event'lerinin çoğu kendi işini yapan özel thread'lerden geliyor (thread pool'un gate thread'i, console logger, Kestrel heartbeat). Doküman da bunu söylüyor: thread pool starvation arıyorsan yalnızca thread pool thread'lerindeki beklemeler ilgilidir. CounterGroup ve AggregationManager satırları ise o sırada açık olan dotnet-counters oturumunun kendisi; ölçüm aracı da ölçülene giriyor. İkincisi, handler'dan gelen 39 event: event bir bekleme başlarken yazılır, trace başlamadan önce zaten bloklanmış thread'ler yeni event üretmez. 10 saniyede 39 yeni bekleme, havuza saniyede yaklaşık 4 yeni thread eklenmesiyle tutarlı; her yeni thread geldiği gibi bir sonraki /summary isteğine bloklanıyor.

.NET 10'da collect-linux: Ne Zaman, Ne Zaman Değil

dotnet-trace'in .NET 10 ile gelen collect-linux komutu, EventPipe yerine Linux'un perf_events altyapısını ve user_events'i kullanır. Dokümandaki farklar: makinedeki bütün process'leri aynı anda izleyebilir, native kütüphane ve kernel event'lerini yakalar, stack'lerde native frame'ler de görünür. Bedeli de ön koşullar: Linux kernel 6.4 ya da üstü ve CONFIG_USER_EVENTS=y, mount edilmiş tracefs, root yetkisi (CAP_PERFMON ya da CAP_SYS_ADMIN), glibc 2.27 ya da üstü ve .NET 10 runtime.

Process'in komutu destekleyip desteklemediğini root gerektirmeyen probe modu söylüyor. Container içinde:

$ 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:
7 dotnet

.NET processes that do NOT support the command:

Process destekliyor, ama ortam desteklemiyor. Container'da root olarak, ek yetki vermeden asıl komutu denedim:

$ dotnet-trace collect-linux -p 7 --duration 00:00:00:03 -o /tmp/linux.nettrace
No providers, profiles, ClrEvents, or PerfEvents were specified, defaulting to trace profiles 'dotnet-common' + 'cpu-sampling'.

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x000000100003801D  Informational(4)    --profile

Linux Perf Events                                                               Enabled By
cpu-sampling                                                                    --profile

Output File    : /tmp/linux.nettrace

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

tracefs'i mount etmek ayrıcalıklı bir container ister ve burada daha temel bir engel var: Docker Desktop'ın VM'indeki (virtual machine, sanal makine) kernel 6.12.72-linuxkit, /proc/config.gz içinde # CONFIG_USER_EVENTS is not set diyor. Yani bu ortamda collect-linux ile trace alamadım; yukarıdaki özellik listesi dokümandan. Pratik kural: hedef bir Linux sunucu ya da node'sa, kernel uygunsa ve root ile tracefs'e erişebiliyorsan, native frame'ler ve "bu sırada makinede başka ne oluyordu" sorusu için collect-linux. Yönetilen bir container platformundaysan, yetkin yoksa ya da yalnızca managed stack'ler yeterliyse klasik collect. Thread pool starvation teşhisi için klasik collect fazlasıyla yetti.

Düzeltme ve Doğrulama

Düzeltme tek kelime: .Result yerine await. Aynı yük, aynı container, /summary-async:

$ dotnet loadgen/bin/Release/net10.0/LoadGen.dll http://localhost:5420/orders/1/summary-async 200 40
requests=38937 errors=0 rps=968.4
p50=204ms p95=210ms p99=222ms max=376ms

Ortanca 47 saniyeden 204 ms'ye indi; bu, bağımlılığın kendi 200 ms'si. Aynı 40 saniyede 200 yerine 38.937 istek bitti. Sayaçlarda thread pool 4 thread'de kaldı, queue 0'da; dotnet-stack 69 yerine 15 thread gösterdi; bizim koddan tek frame, app.Run()'da bekleyen ana thread'deydi. Düzeltmeyi "artık hızlı" hissiyle değil, teşhiste kullandığın aynı ölçümle doğrula: aynı yük, aynı sayaçlar, aynı stack sorgusu.

"Min thread sayısını 200 yapalım" (ThreadPool.SetMinThreads) ise düzeltme değil, ağrı kesici. Thread'ler yine bloklanır, yalnızca havuz daha hızlı büyür; her thread'in kendi stack belleği vardır ve yük 400 olduğunda aynı tablo geri gelir.

Üretimde Dikkat

Production'da bu araçları çalıştırmak güvenli, ama sınırlı tutmak şartıyla:

• Her zaman --duration ver. Unutulmuş bir trace oturumu diski doldurur. Benim 5 ve 10 saniyelik iki trace dosyam 4,4'er MB'tı; yoğun bir serviste aynı süre çok daha büyük olur.
• Dokümana göre in-memory buffer varsayılanı 256 MB ve varsayılan mod Drop: event'ler diske yetişemezse atılır, uygulama yavaşlatılmaz. Event'leri kaybetmemek için Block modu var, ama .NET 11 hedef runtime ister ve uygulamayı yavaşlatabilir; production'da bunu açmam.
• Trace'i durdurmak dakikalar sürebilir: runtime, kayda giren bütün managed kod için tip ve method bilgisini gönderir. Komut "Stopping the trace" dedikten sonra beklemeye hazır ol, process'i öldürme.
• Örnekleme maliyeti sıfır değil: dotnet-sampled-thread-time her milisaniyede bütün thread'lerin stack'ini alır, 200 thread'li bir process'te bu hissedilir. Önce yalnızca --clrevents waithandle gibi dar bir seçimle başla.
• Araçlar hedef process'le aynı kullanıcıyla (ya da root ile) ve Linux'ta aynı TMPDIR ile çalışmalı; aksi hâlde bağlantı zaman aşımına uğrar. Aynı container'da docker exec en kolay yol.
• dotnet-stack ve dotnet-counters'ı nöbet runbook'una koy; dotnet-trace'i süre ve profil sınırlarıyla birlikte.

Sık Düşülen Tuzaklar

CPU düşükken "sorun performans değil" demek. Bu vakada CPU boştu; sorun beklemekti. Düşük CPU ve yüksek gecikme birlikteyse ilk şüphen bloklanmış thread'ler olsun.

dotnet-counters collect CSV'sindeki thread ve queue değerlerini mutlak değer sanmak. Bu sürümde saniyelik değişim olarak yazıldılar; grafiği çizmeden önce topla ya da monitor ile canlı bak.

Trace'teki bütün bekleme event'lerini suçlu saymak. Console logger, gate thread ve ölçüm aracının kendi thread'leri her zaman bekler. Thread pool thread'lerini ve kendi kodunu içeren stack'leri ayır.

Tek bir dotnet-stack çıktısıyla ara sıra olan bir sorunu dışlamak. Snapshot o an temizse, sorun yok demek değildir; ara sıra olan bloklamalar için süreli trace al.

Health check'in yeniden başlattığı pod'u "kendiliğinden düzeldi" diye kapatmak. Restart, thread pool'u sıfırlar ve kanıtı siler. Restart'tan önce dotnet-stack ya da dump almayı runbook'a yaz.

Küçük Bir Deneme

★☆☆ Aynı servisi --cpus 8 ile başlat ve bloklayan endpoint'e aynı yükü ver. Thread sayısı nereden başlıyor, p50 ne kadar değişiyor? Sonucu varsayılan minimum thread sayısıyla ilişkilendir.

★★☆ .Result yerine Task.Run(() => inventory.GetStockAsync(id)).Result kullanan bir endpoint daha ekle ve aynı ölçümleri yap. dotnet-stack çıktısında stack'in tepesi nasıl değişiyor, bekleme event sayısı ne oluyor?

★★★ WaitReport uygulamasını, yalnızca stack'inin dibinde WorkerThreadStart olan, yani thread pool thread'lerindeki beklemeleri sayacak ve her biri için bekleme süresini (WaitHandleWait/Stop ile eşleştirerek) raporlayacak şekilde geliştir.

Dump ve trace bize "ne oldu" sorusunun teknik cevabını verdi. Ama her incident'ın sonunda daha zor bir soru kalır: bu neden oldu ve bir daha olmaması için ne değişmeli? Sonraki yazıda 5 Whys, fishbone ve blameless postmortem ile root cause analysis'e geçiyoruz.