Diagnose, Fix, Prove: Bookstore'da Uçtan Uca Bir Performans Vakası

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

Önce Tahmin Et

Sitedeki serilerin ortak örnek uygulaması Bookstore (bir online kitapçı) kampanya haftasına giriyor ve checkout endpoint'i saniyede 700 istek alacak. Kod incelemesinde üç şüpheli işaretlendi: fiyat hesabı her istekte yeni bir JsonSerializerOptions oluşturuyor (IDE'nin CA1869 önerisi tam olarak bunu söylüyor), 2.000 kampanya kuralını her istekte JSON'dan okuyor ve hesaplanan teklifleri sepet içeriğine göre 30 dakika cache'liyor. Sence p99'u yakan hangisi, ya da hangileri? İkinci soru: sunucunun kendi ölçtüğü p99 ile k6'nın gördüğü p99 aynı mı olur? Bu yazıda tahminle değil, sırayla dotnet-counters, dotnet-trace ve dotnet-gcdump ile cevaplıyoruz; düzeltmeyi de BenchmarkDotNet ve k6 ile kanıtlıyoruz.

Başlangıç: Checkout'un p99'u SLO'yu Yakıyor

Ekibin checkout için bir SLO'su (Service Level Objective; servisin hedeflenen güvenilirlik seviyesi) var: p99 100 ms'nin altında. SLO ve error budget'ın nasıl belirlendiği, yanma hızına göre alarm kurmak SRE (Site Reliability Engineering; servis güvenilirliğini mühendislik yöntemleriyle yönetme yaklaşımı) ve Production Incident'ları serisinin konusu; burada alarm çalmış ve teşhis bize kalmış. Production pod'unun boyutuyla aynı bir container kurdum (1 CPU, 1 GiB) ve kampanya trafiğini k6'nın sabit hızlı executor'üyle verdim: rastgele sepetler, 1-4 kalem, her beş sepetten birinde kupon, saniyede 700 istek, 60 saniye.

docker run -d --name profseries-api --cpus 1 --memory 1g -p 5481:8080 profseries-api:lab09
k6 run -e RATE=700 -e DURATION=60s checkout.js

http_req_duration..............: avg=117.24ms p(50)=1.22ms p(95)=476.06ms p(99)=537.34ms max=701.17ms
http_reqs......................: 35658 594.281181/s
dropped_iterations.............: 6343 105.713319/s

p99 537 ms, hedefin beş katı. Ortanca istek 1,2 ms; yani isteklerin çoğu hızlı, bir kısmı çok yavaş. Daha kötüsü dropped_iterations: k6'nın açtığı 200 sanal kullanıcının hepsi cevap beklediği için 700 yerine saniyede 594 istek gönderebildi. Servis hedeflenen yükü taşıyamıyor.

Adım 1: dotnet-counters ile Geniş Bakış

01'deki kural: önce ucuz ve geniş bakış. Yük sürerken System.Runtime ve Microsoft.AspNetCore.Hosting'i 10 saniyelik aralıklarla CSV'ye (virgülle ayrılmış düz metin) kaydettim ve her aralığı tek satıra indirdim:

docker exec profseries-api dotnet-counters collect -p 1 --refresh-interval 10 --format csv \
    -o /tmp/co-slow.csv --counters System.Runtime,Microsoft.AspNetCore.Hosting

    time  p50 ms  p99 ms alloc MB/s  gen2  pause ms  heap MB   cpu
01:24:20     2.3    51.5        253     0       445       83  0.99
01:24:30     0.8     2.8        423     0       617       88  0.80
01:24:40     0.7     1.7        441     0       394       96  0.60
01:24:50     0.8     6.0        418     0       772      101  0.77
01:25:00     0.8     4.0        435     0       698      106  0.74

Üç sinyal var. Allocation saniyede 420-440 MB; saniyede 600 istek için istek başına 700 KB civarı, bir fiyat teklifi için çok fazla. GC (garbage collector; kullanılmayan object'leri temizleyen runtime bileşeni) her 10 saniyenin 400-770 ms'sinde thread'leri durduruyor. GC heap'i ise yük altında 83 MB'tan 106 MB'a tırmanıyor ve inmiyor.

Tahmin sorusunun ikinci cevabı da bu tabloda. Sunucunun kendi http.server.request.duration histogram'ına göre p99 çoğu aralıkta 2-6 ms; k6'ya göre 537 ms. Aradaki fark büyük olasılıkla isteğin ASP.NET Core pipeline'ına girmeden önce geçirdiği zaman: bağlantının kabul edilmesi, isteğin okunması ve bunlar için CPU ile thread bulunması. Histogram bu bekleyişi görmüyor. CPU sütunu ise 1'in altında görünüyor, ama bu 10 saniyelik bir ortalama. Senaryoyu hiçbir araç bağlamadan tekrarlayıp yük öncesi ve sonrası container'ın cgroup istatistiğini (/sys/fs/cgroup/cpu.stat) okudum: 60 saniyelik yükte 603 CFS (Completely Fair Scheduler; Linux'un CPU zamanını paylaştıran zamanlayıcısı) periyodunun 138'inde, yani yüzde 23'ünde container CPU limit'ine takılıp beklemiş ve toplam 8 saniye throttle edilmiş. GC'nin ürettiği CPU patlamaları kotayı dolduruyor, kota dolunca bütün thread'ler bir sonraki periyodu bekliyor. CPU throttling'in mekaniği Kubernetes serisinin "Resource Request ve Limit'ler: QoS, OOMKilled, CPU Throttling ve Container'da .NET GC" yazısında. Ders şu: sunucu tarafı histogram'ı tek başına SLO kanıtı değil, istemcinin gördüğünü de ölç.

Adım 2: dotnet-trace ile Sıcak Yol

Counters "çok allocation ve GC" diyor; kimin yaptığını trace söyler. Yük altında 10 saniyelik varsayılan bir trace ve 04'teki allocation sampling ile ikinci bir trace aldım, ikisini de 06'daki Bookstore.TraceStats ile okudum. Önce yalnızca checkout isteklerini içeren örnekler:

dotnet run -c Release -- cpu checkout-cpu.nettrace \
    --inc CheckoutEndpoints --exc UNMANAGED_CODE_TIME --foldpats CPU_TIME --fold 2

 Exc %  Inc %  Name   (total 13,902 ms)
  93.0   93.0  System.Private.CoreLib!System.Threading.Thread.<PollGC>g__PollGCWorker|67_0()
   2.8    2.8  System.Text.Json!System.Text.Json.Serialization.Metadata.DefaultJsonTypeInfoResolver.CreateTypeInfoCore()
   1.3   92.1  System.Text.Json!System.Text.Json.Serialization.JsonConverter`1[System.__Canon].TryRead()
   1.0    3.8  System.Text.Json!System.Text.Json.Serialization.Metadata.JsonTypeInfo.Configure()
   0.7   97.5  Bookstore.Api!Bookstore.Api.Checkout.PricingService.PriceNaive()

Checkout'un zamanının yüzde 97,5'i PriceNaive'in altında, yüzde 92'si JSON okumanın içinde ve yüzde 93'ü PollGC'de, yani thread'ler GC için durdurulmayı bekliyor. Yeni options'ın maliyeti de görünüyor: metadata'yı yeniden kuran CreateTypeInfoCore ve Configure toplamda yüzde 6,6. Gerçek ama küçük. Allocation trace'i ne ayrıldığını söylüyor:

requests 6625, 618.0 KB per request
      126.4 KB  Bookstore.Api.Checkout.CampaignRule
      110.0 KB  System.String
      109.8 KB  System.Text.Json.ArgumentState
       94.9 KB  System.Int32
       63.0 KB  System.Decimal
       47.1 KB  Bookstore.Api.Checkout.DiscountKind

İstek başına 618 KB ve listenin tamamı kampanya kurallarını okumaktan geliyor. Int32, Decimal ve DiscountKind satırları ilginç: CampaignRule constructor parametreli bir record olduğu için System.Text.Json argümanları önce bir ArgumentState'te topluyor ve value type'ları kutulayarak (boxing) tutuyor. Her istekte 2.000 kural, kural başına birkaç kutulanmış değer.

Adım 3: gcdump ile Büyüyen Tip

Trace sıcak yolu verdi ama counters'taki ikinci sinyali, büyüyen heap'i açıklamıyor. 05'teki yöntemle yük sürerken 27 saniye arayla iki gcdump aldım ve diff script'iyle karşılaştırdım:

     80,258,943  GC Heap bytes
     94,901,270  GC Heap bytes

       Bytes +   Count 1   Count 2  Type
     3,704,240    41,417    87,720  Bookstore.Api.Checkout.PricedLine
     1,925,976    16,604    35,123  Microsoft.Extensions.Caching.Memory.CacheEntry
     1,037,064    16,603    35,122  Bookstore.Api.Checkout.Quote
     1,037,064    16,603    35,122  Bookstore.Api.Checkout.PricedLine[]
       888,912    16,603    35,122  Node<System.String,Microsoft.Extensions.Caching.Memory.CacheEntry>

CacheEntry, Quote ve dictionary düğümü aynı sayıyla artıyor: her teklif cache'e giriyor ve 30 dakikalık sliding expiration yüzünden orada kalıyor. Bir cache'in büyümesi tek başına sorun değil; asıl soru işe yarıyor mu. Lab'a MemoryCache'in istatistiklerini dönen bir teşhis endpoint'i eklemiştim (TrackStatistics = true ile):

curl -s localhost:5481/diag/cache

{"currentEntryCount":49367,"currentEstimatedSize":null,"totalMisses":49367,"totalHits":0}

49.367 kayıt, sıfır hit. Anahtar sepetin tamamı olduğu için iki müşterinin aynı sepeti aynı yarım saatte göndermesi neredeyse imkânsız; daha önceki 3 dakikalık bir koşuda 197.966 ıska karşısında 5 hit saymıştım. Bu cache hiçbir isteği hızlandırmıyor, yalnızca 30 dakika boyunca belleği dolduruyor ve gen2'nin taradığı canlı veriyi büyütüyor. Size limit'siz cache pattern'i 05'te ve Caching serisinin IMemoryCache yazısında geçti; burada yeni olan, onu bir hit oranıyla birlikte ölçmek.

Kök Neden ve Düzeltme

Üç aracın verisi birleşince tablo net: ana maliyet her istekte 2.000 kuralın JSON'dan okunması (CPU, allocation, GC ve dolayısıyla throttling); ikinci sorun hiç hit almayan ama belleği büyüten cache; yeni JsonSerializerOptions ise ölçülebilir ama küçük bir kalem. Sorunlu kod:

// yavaş sürüm: kampanya kurallarını her çağrıda yepyeni serializer options ile okuyor
public Quote PriceNaive(CheckoutRequest request)
{
    JsonSerializerOptions options = new(JsonSerializerDefaults.Web)
    {
        Converters = { new JsonStringEnumConverter() }
    };
    List<CampaignRule> rules = JsonSerializer.Deserialize<List<CampaignRule>>(campaigns.RulesJson, options)!;
    return Calculate(request, rules);
}

// yavaş sürüm: teklifler sepet içeriğine göre 30 dakika cache'leniyor, ıskada PriceNaive
app.MapPost("/api/checkout", (CheckoutRequest request, PricingService pricing, IMemoryCache cache) =>
{
    string key = "quote:" + JsonSerializer.Serialize(request);
    Quote quote = cache.GetOrCreate(key, entry =>
    {
        entry.SlidingExpiration = TimeSpan.FromMinutes(30);
        return pricing.PriceNaive(request);
    })!;
    return Results.Ok(quote);
});

Düzeltme üç parça. Kurallar CampaignStore'da bir kez, paylaşılan options ile okunuyor; gerçek bir sistemde arka ofis yeni kural yayınladığında yeniden kurulur. Fiyat hesabı hazır listeyi kullanıyor. Cache kalkıyor, çünkü hesap artık cache'e gerek duymayacak kadar ucuz:

public sealed class CampaignStore
{
    public static readonly JsonSerializerOptions RuleOptions = new(JsonSerializerDefaults.Web)
    {
        Converters = { new JsonStringEnumConverter() }
    };

    private readonly Lazy<IReadOnlyList<CampaignRule>> _rules;

    // kurucu: kuralları üretip RulesJson'a yazıyor (kısaltıldı)

    public string RulesJson { get; }

    // bir kez okunup paylaşılıyor; gerçek bir store arka ofis yeni kural yayınlayınca bunu yeniden kurar
    public IReadOnlyList<CampaignRule> Rules => _rules.Value;
}

// düzeltilmiş sürüm: kurallar bir kez okunmuş, options paylaşılıyor
public Quote Price(CheckoutRequest request) => Calculate(request, campaigns.Rules);

// düzeltilmiş sürüm: fiyat hesabı her istekte yapılacak kadar ucuz, cache'e gerek yok
app.MapPost("/api/checkout-v2", (CheckoutRequest request, PricingService pricing) =>
    Results.Ok(pricing.Price(request)));

İki endpoint'in aynı sepet için aynı teklifi döndüğünü curl ile karşılaştırarak doğruladım.

Kanıt: BenchmarkDotNet ve Aynı Yükle k6

İlk kanıt mikro seviyede: değişikliğin method'u gerçekten hızlandırdığını ve şüphelilerin payını ayrı ayrı göstermek. Benchmark'ın ayrıntılı kullanımı (parametreler, diagnoser'lar, CI'da regresyon yakalamak) Performance ve Load Testing serisinin BenchmarkDotNet yazısında; burada yalnızca kanıt aracı olarak kullanıyoruz:

[MemoryDiagnoser]
public class PricingBenchmarks
{
    private readonly CampaignStore _campaigns = new();
    private PricingService _pricing = null!;
    private CheckoutRequest _request = null!;

    [GlobalSetup]
    public void Setup()
    {
        _pricing = new PricingService(new CatalogStore(), _campaigns);
        _request = new CheckoutRequest(42, [new(10, 2), new(77, 1), new(1_234, 3)], "BOOK25");
        _ = _pricing.Price(_request);
    }

    [Benchmark(Baseline = true)]
    public Quote PriceNaive() => _pricing.PriceNaive(_request);

    [Benchmark]
    public Quote Price() => _pricing.Price(_request);

    [Benchmark]
    public List<CampaignRule> ParseRulesWithNewOptions() =>
        JsonSerializer.Deserialize<List<CampaignRule>>(_campaigns.RulesJson,
            new JsonSerializerOptions(JsonSerializerDefaults.Web) { Converters = { new JsonStringEnumConverter() } })!;

    [Benchmark]
    public List<CampaignRule> ParseRulesWithSharedOptions() =>
        JsonSerializer.Deserialize<List<CampaignRule>>(_campaigns.RulesJson, CampaignStore.RuleOptions)!;
}

| Method                      | Mean      | Error    | StdDev   | Ratio | Gen0     | Gen1    | Allocated | Alloc Ratio |
|---------------------------- |----------:|---------:|---------:|------:|---------:|--------:|----------:|------------:|
| PriceNaive                  | 646.46 us | 7.827 us | 7.321 us |  1.00 | 148.4375 | 39.0625 |  626161 B |       1.000 |
| Price                       |  25.39 us | 0.162 us | 0.144 us |  0.04 |   0.0916 |       - |     496 B |       0.001 |
| ParseRulesWithNewOptions    | 616.92 us | 3.140 us | 2.784 us |  0.95 | 144.5313 | 42.9688 |  625615 B |       0.999 |
| ParseRulesWithSharedOptions | 601.58 us | 4.645 us | 4.345 us |  0.93 | 127.9297 | 41.9922 |  591880 B |       0.945 |

(Linux container'da, Release, .NET 10.0.15; RatioSD sütununu çıkardım.) Tahmin sorusunun cevabı bu tabloda. Yeni options ile paylaşılan options arasındaki fark yalnızca yüzde 2,5 ve 33 KB; System.Text.Json aynı ayarlara sahip options örnekleri için metadata'yı önemli ölçüde yeniden kullanıyor. CA1869'un önerisi doğru ve uygulamaya değer, ama bu vakada p99'u yakan o değil. Asıl kazanç kuralları bir kez okumaktan geliyor: istek başına 646 µs ve 611 KB'tan 25 µs ve 496 byte'a. Kod incelemesindeki en göze batan şüpheliyi düzeltip ölçmeden "bitti" deseydik, SLO yanmaya devam edecekti.

İkinci kanıt uçtan uca: aynı container boyutu, aynı ısınma, aynı k6 senaryosu, yalnızca endpoint farklı.

p99 537 ms'den 1,5 ms'ye indi ve servis hedef yükü tam olarak taşıdı. Aynı ölçümü araçsız bir kez daha tekrarladım; yavaş sürümde p99 483 ms çıktı (saniyede 641 istek, iterasyonların yüzde 8'i düştü), düzeltilmiş sürümde 1,08 ms. Tek koşu yerine iki koşu, sonucun şans eseri olmadığını göstermek için en az şart.

Rapor Şablonu ve "Ölçmeden Değiştirmedik" Listesi

Bu tür bir vakayı ekibe bir sayfalık raporla anlatıyorum. Şablon şu başlıklardan oluşuyor: belirti (hangi SLO, ne zamandan beri, istemci tarafı sayı), ortam (pod boyutu, sürüm, yük profili), adım adım bulgular (her araç için komut, bir satırlık sonuç, dosyanın yeri), kök neden, düzeltme (commit), kanıt (mikro benchmark ve uçtan uca önce/sonra tablosu, kaç koşu), açık kalanlar ve izlenecek metric. Postmortem kültürünün geri kalanı SRE serisinin konusu. Rapora girmeden önce kendime sorduğum liste:

• Sorunu istemci tarafında, hedef yükte, production'a benzer kaynak limitiyle tekrar üretebildim mi?
• Her şüpheliyi ayrı ölçtüm mü, yoksa kod incelemesindeki ilk bulguyu mu düzelttim?
• Sunucu tarafı ile istemci tarafı sayıları neden farklı, açıklayabiliyor muyum?
• Kaldırdığım ya da eklediğim cache'in hit oranını ölçtüm mü?
• Düzeltmeden sonra aynı yükle, en az iki kez, aynı araçlarla tekrar ölçtüm mü?
• Bu sorunu bir dahaki sefere erken yakalayacak metric ya da alarm hangisi?

Üretimde Dikkat

Bu vakadaki teşhis adımlarının hepsi production'da da yapılabilir, ama sırası önemli. dotnet-counters'ı istediğin kadar açık tut. Trace'i kısa al ve 1 CPU'luk bir pod'da trace'in kendisinin de CPU yediğini unutma; throttling altındaki bir pod'da 10 saniyelik trace bile p99'u bir süre daha kötüleştirebilir. gcdump'ı bir gen2 tetiklediği için tek instance'ta ve trafiği azaltarak al. Bu adımları elle yapmak yerine 08'deki collection rule'larla p99 eşiğine bağlamak, bir dahaki kampanyada gece 3'te kimsenin uyanmasına gerek bırakmaz.

Bu kuralların ve kampanya trafiğinin kendisi de bir test: k6 ile hedef yükte, production pod boyutunda yük testi yapılmış olsaydı bu sorun kampanyadan önce bulunurdu. Yük testinin nasıl tasarlanacağı Performance ve Load Testing serisinin konusu.

Sık Düşülen Tuzaklar

• Kod incelemesindeki en tanıdık anti-pattern'i (burada yeni JsonSerializerOptions) suçlu ilan edip ölçmemek; bu vakada payı yüzde 2,5'ti.
• Sunucu tarafı histogram'ına bakıp "p99 6 ms, sorun yok" demek; istemci 537 ms görüyordu.
• CPU ortalaması 1'in altında diye CPU limit'ini dışlamak; cgroup'un throttling sayaçlarına bak.
• Hit oranını ölçmeden cache eklemek ya da kaldırmak.
• Mikro benchmark'ı tek kanıt saymak: 25 kat hızlanan bir method, uçtan uca sonucu ancak sıcak yol oysa değiştirir.
• Önce/sonra ölçümünü farklı container boyutunda, farklı ısınmayla ya da tek koşuyla yapmak.

Küçük Bir Deneme

★☆☆ Lab'ı --cpus 1 ve --cpus 4 ile iki kez başlat, yavaş checkout'a aynı 700/sn yükü ver ve iki durumda cpu.stat'taki nr_throttled ile k6'nın p99'unu karşılaştır.

★★☆ CampaignRule'u parametresiz constructor'lı bir class'a çevir ya da bir JsonSerializerContext ile source generation kullan. ParseRulesWithSharedOptions benchmark'ında ArgumentState ve kutulama allocation'larının kaybolup kaybolmadığını ölç.

★★★ Teklif cache'ini kaldırmak yerine işe yarar hâle getir: anahtarı sepetin tamamı değil kitap ve kupon olsun, SizeLimit ve kısa bir expiration ekle. Gerçekçi bir trafik karışımında (popüler kitaplar daha sık) hit oranını ve p99'u cache'siz sürümle karşılaştır; cache'in hangi trafikte kazandırdığını bul.

Bu vakada kullandığımız araçların bir kısmı .NET 9 ve 10'da geldi, bir kısmı .NET 11 ile değişti. Serinin son yazısında .NET 8'den .NET 11'e diagnostics'te nelerin değiştiğini topluyoruz: System.Runtime Meter'ı, yeni dotnet-trace profile'ları, collect-linux, runtime async ile sadeleşen stack'ler ve process içinde yazılan crash report.