Diagnose, Fix, Prove: An End-to-End Performance Case in Bookstore

Version note: The code in this post was built and run with .NET 10 (runtime 10.0.15 in the container), dotnet-counters, dotnet-trace and dotnet-gcdump 10.0.750501, Microsoft.Diagnostics.Tracing.TraceEvent 4.0.0, BenchmarkDotNet 0.15.8 and k6 2.4.0 for load.

Guess First

Bookstore, the online bookstore used as the shared example across this site's series, is heading into campaign week, and its checkout endpoint will get 700 requests per second. A code review flagged three suspects: the pricing code creates a new JsonSerializerOptions on every request (exactly what the IDE's CA1869 suggestion says), it reads 2,000 campaign rules from JSON on every request, and it caches computed quotes by cart content for 30 minutes. Which one burns the p99, or which ones? Second question: is the p99 the server measures itself the same as the p99 k6 sees? In this post we answer not by guessing but with dotnet-counters, dotnet-trace and dotnet-gcdump, in that order, and we prove the fix with BenchmarkDotNet and k6.

The Start: Checkout's p99 Is Burning the SLO

The team has an SLO for checkout: p99 below 100 ms. How SLOs and error budgets are set and how to alert on burn rate is the topic of the SRE and Production Incidents series; here the alert has fired and the diagnosis is ours. I set up a container the same size as the production pod (1 CPU, 1 GiB) and drove campaign traffic with k6's constant-rate executor: random carts, 1-4 lines, a coupon in every fifth cart, 700 requests per second, 60 seconds.

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

A p99 of 537 ms, five times the target. The median request takes 1.2 ms; so most requests are fast and some are very slow. Worse is dropped_iterations: because all 200 virtual users k6 opened were waiting for answers, it could send only 594 requests per second instead of 700. The service cannot carry the target load.

Step 1: The Wide View with dotnet-counters

The rule from 01: a cheap, wide view first. While the load ran I recorded System.Runtime and Microsoft.AspNetCore.Hosting to CSV in 10-second intervals and reduced each interval to a single line:

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

There are three signals. Allocation runs at 420-440 MB per second; at 600 requests per second that is around 700 KB per request, far too much for a price quote. GC stops the threads for 400-770 ms of every 10 seconds. And the GC heap climbs from 83 MB to 106 MB under load and does not come down.

The answer to the second guess is in this table too. According to the server's own http.server.request.duration histogram, p99 is 2-6 ms in most intervals; according to k6 it is 537 ms. The difference is most likely the time a request spends before it enters the ASP.NET Core pipeline: accepting the connection, reading the request, and finding CPU and a thread for both. The histogram does not see that wait. The CPU column looks below 1, but it is a 10-second average. I repeated the scenario with no tool attached and read the container's cgroup statistics (/sys/fs/cgroup/cpu.stat) before and after the load: in 60 seconds of load, in 138 of 603 CFS periods, that is 23 percent, the container hit its CPU limit and waited, and it was throttled for 8 seconds in total. The CPU bursts produced by GC fill the quota, and once the quota is full every thread waits for the next period. The mechanics of CPU throttling are covered in the Kubernetes series post "Resource Requests and Limits: QoS, OOMKilled, CPU Throttling and the .NET GC in Containers". The lesson: the server-side histogram alone is not evidence for an SLO; measure what the client sees too.

Step 2: The Hot Path with dotnet-trace

Counters say "lots of allocation and GC"; a trace tells you who does it. Under load I took a 10-second default trace and a second trace with the allocation sampling from 04, and read both with Bookstore.TraceStats from 06. First, only the samples that contain checkout requests:

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()

97.5 percent of checkout's time is under PriceNaive, 92 percent inside JSON reading, and 93 percent in PollGC, meaning threads are waiting to be suspended for GC. The cost of the new options shows up as well: CreateTypeInfoCore and Configure, which rebuild metadata, add up to 6.6 percent. Real, but small. The allocation trace tells you what is allocated:

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

618 KB per request, and the whole list comes from reading the campaign rules. The Int32, Decimal and DiscountKind rows are interesting: because CampaignRule is a record with a parameterized constructor, System.Text.Json first collects the arguments in an ArgumentState and holds value types boxed. 2,000 rules on every request, a few boxed values per rule.

Step 3: The Growing Type with gcdump

The trace gave the hot path but does not explain the second signal from counters, the growing heap. Using the method from 05, I took two gcdumps 27 seconds apart while the load ran and compared them with the diff script:

     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 and the dictionary node grow by the same count: every quote goes into the cache and stays there because of the 30-minute sliding expiration. A growing cache is not a problem by itself; the real question is whether it helps. I had added a diagnostic endpoint to the lab that returns MemoryCache's statistics (with TrackStatistics = true):

curl -s localhost:5481/diag/cache

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

49,367 entries, zero hits. Since the key is the entire cart, two customers sending the same cart within the same half hour is next to impossible; in an earlier 3-minute run I counted 5 hits against 197,966 misses. This cache speeds up no request; it only fills memory for 30 minutes and enlarges the live data gen2 has to scan. The cache-without-a-size-limit pattern came up in 05 and in the Caching series post on IMemoryCache; what is new here is measuring it together with a hit rate.

Root Cause and Fix

Putting the data from the three tools together, the picture is clear: the main cost is reading 2,000 rules from JSON on every request (CPU, allocation, GC and therefore throttling); the second problem is a cache that never gets a hit but grows memory; the new JsonSerializerOptions is a measurable but small item. The problematic code:

// slow version: parses all campaign rules with brand new serializer options on every call
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);
}

// slow version: quotes cached by cart content for 30 minutes, priced with PriceNaive on a miss
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);
});

The fix has three parts. The rules are read once in CampaignStore, with shared options; a real system would rebuild them when the back office publishes new rules. Pricing uses the ready list. The cache goes away, because the computation is now cheap enough not to need one:

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

    private readonly Lazy<IReadOnlyList<CampaignRule>> _rules;

    // constructor: generates the rules and writes them to RulesJson (trimmed)

    public string RulesJson { get; }

    // parsed once and shared; a real store would rebuild this when the back office publishes new rules
    public IReadOnlyList<CampaignRule> Rules => _rules.Value;
}

// fixed version: rules parsed once, options shared
public Quote Price(CheckoutRequest request) => Calculate(request, campaigns.Rules);

// fixed version: pricing is cheap enough to do on every request, no cache needed
app.MapPost("/api/checkout-v2", (CheckoutRequest request, PricingService pricing) =>
    Results.Ok(pricing.Price(request)));

I verified with curl that both endpoints return the same quote for the same cart.

Proof: BenchmarkDotNet and k6 Under the Same Load

The first proof is at the micro level: showing that the change really speeds up the method, and the share of each suspect separately. Advanced benchmark usage (parameters, diagnosers, catching regressions in CI) is covered in the BenchmarkDotNet post of the Performance and Load Testing series; here we use it only as a proof tool:

[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 |

(In a Linux container, Release, .NET 10.0.15; I removed the RatioSD column.) The answer to the guess is in this table. The difference between new and shared options is only 2.5 percent and 33 KB; System.Text.Json largely reuses metadata for options instances with the same settings. CA1869's suggestion is right and worth applying, but in this case it is not what burns the p99. The real gain comes from reading the rules once: from 646 µs and 611 KB per request to 25 µs and 496 bytes. Had we fixed the most conspicuous suspect from the code review and called it done without measuring, the SLO would have kept burning.

The second proof is end to end: same container size, same warm-up, same k6 scenario, only the endpoint differs.

The p99 dropped from 537 ms to 1.5 ms, and the service carried exactly the target load. I repeated the same measurement once more without tools; the slow version gave a p99 of 483 ms (641 requests per second, 8 percent of iterations dropped), the fixed version 1.08 ms. Two runs instead of one are the bare minimum to show the result is not luck.

A Report Template and the "We Did Not Change It Without Measuring" List

I explain a case like this to the team with a one-page report. The template has these headings: symptom (which SLO, since when, the client-side number), environment (pod size, version, load profile), findings step by step (for each tool the command, a one-line result, where the file is), root cause, fix (commit), proof (micro-benchmark and end-to-end before/after table, how many runs), open items and the metric to watch. The rest of postmortem culture is the topic of the SRE series. The list I ask myself before writing the report:

• Could I reproduce the problem on the client side, at the target load, with a resource limit like production's?
• Did I measure each suspect separately, or did I fix the first finding from the code review?
• Can I explain why the server-side and client-side numbers differ?
• Did I measure the hit rate of the cache I removed or added?
• After the fix, did I measure again under the same load, at least twice, with the same tools?
• Which metric or alert would catch this problem early next time?

In Production

Every diagnostic step in this case can be done in production as well, but the order matters. Keep dotnet-counters running as long as you like. Take traces short, and remember that in a 1-CPU pod the trace itself eats CPU too; in a throttled pod even a 10-second trace can make p99 worse for a while. Take gcdumps on a single instance with reduced traffic, since each triggers a gen2. Tying these steps to a p99 threshold with the collection rules from 08, instead of doing them by hand, means nobody has to wake up at 3 a.m. during the next campaign.

These rules and the campaign traffic itself are also a test: had a load test been run with k6 at the target load and at production pod size, this problem would have been found before the campaign. How to design a load test is the topic of the Performance and Load Testing series.

Common Pitfalls

• Declaring the most familiar anti-pattern from the code review (here the new JsonSerializerOptions) the culprit without measuring; in this case its share was 2.5 percent.
• Looking at the server-side histogram and saying "p99 is 6 ms, all good"; the client saw 537 ms.
• Ruling out the CPU limit because the CPU average is below 1; look at the cgroup's throttling counters.
• Adding or removing a cache without measuring its hit rate.
• Treating a micro-benchmark as the only proof: a method that gets 25 times faster changes the end-to-end result only if it is on the hot path.
• Doing the before/after measurement with a different container size, a different warm-up or a single run.

A Small Experiment

★☆☆ Start the lab twice, with --cpus 1 and with --cpus 4, put the same 700/s load on the slow checkout and compare nr_throttled in cpu.stat and k6's p99 in the two cases.

★★☆ Turn CampaignRule into a class with a parameterless constructor, or use source generation with a JsonSerializerContext. Measure whether the ArgumentState and boxing allocations disappear in the ParseRulesWithSharedOptions benchmark.

★★★ Instead of removing the quote cache, make it useful: let the key be the book and the coupon rather than the whole cart, and add a SizeLimit and a short expiration. With a realistic traffic mix (popular books more often), compare the hit rate and p99 with the cache-free version; find the traffic in which the cache pays off.

Some of the tools we used in this case arrived in .NET 9 and 10, and some changed with .NET 11. In the last post of the series we gather what changed in diagnostics from .NET 8 to .NET 11: the System.Runtime Meter, new dotnet-trace profiles, collect-linux, stacks simplified by runtime async, and crash reports written inside the process.