Allocation and GC Analysis: gc-verbose, Allocation Sampling, the LOH and Server GC/DATAS Settings

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

Guess First

Every morning Bookstore's accounting team downloads a CSV file of 200,000 orders; the file is 12 MB. At month end eight people start downloading at the same time and the service slows down. Two questions: how many bytes could a single download request allocate on the managed heap, 12 MB, 24 MB or 60 MB? And which setting helps more: moving from Server GC to Workstation GC, turning DATAS off, or neither? The answers are in the measurement tables.

When Is It a GC Problem? The Case: A CSV Export

The endpoint builds the whole file in memory, the way I often see in real projects:

// whole file in memory: StringBuilder -> string -> byte[]
app.MapGet("/api/reports/orders.csv", (OrderStore orders) =>
{
    StringBuilder csv = new();
    csv.Append(Header);
    foreach (Order order in orders.All)
    {
        csv.Append(CultureInfo.InvariantCulture,
            $"{order.Id},{order.CustomerId},{order.PlacedAt:O},{order.Total},{order.Status}\n");
    }

    byte[] bytes = Encoding.UTF8.GetBytes(csv.ToString());
    return Results.File(bytes, "text/csv", "orders.csv");
});

I applied a 30-second k6 load with 8 virtual users and recorded System.Runtime with dotnet-counters collect at the same time. The median of the 5-second intervals: 92 requests per second, p95 123 ms; 3.83 of 4 CPUs busy; 5.5 GB of allocation per second; 924 gen0, 882 gen1 and 1,614 gen2 GCs per minute; 20.5 percent of the time in GC pauses; LOH at 170 MB at the last GC (peak 218 MB); GC committed memory 653 MB, working set 862 MB.

This is the signature of a GC problem. 27 gen2s per second, so at least one full GC per request; a fifth of the CPU goes to pauses in which threads stand still. Divide 5.5 GB by 92 requests and you get the answer to the first guessing question: about 60 MB per request, five times the file size. In a normal API, gen2s do not exceed a few per minute; the most common reason for gen2s this frequent is the LOH, where objects of 85,000 bytes and above are allocated. Objects on the LOH count as part of gen2 and are collected only in a gen2 GC; once LOH allocation passes a certain budget, the GC triggers a gen2 directly.

Watch out for an old misreading here. The "% Time in GC since last GC" counter of .NET 8 and earlier described only the interval between the last two GCs and could show 0 percent one second and 90 percent the next. The new dotnet.gc.pause.time is total pause time; divide its increase by the length of the interval and you have the real share. Then there is background GC: much of a gen2 can run in the background while app threads keep running, so "the GC is running" and "threads are paused" are not the same thing. What users feel is the pause.

gc-verbose: Tying Allocations to Stacks

Metrics say there are a lot of allocations; a trace says who makes them. dotnet-trace has two GC profiles: gc-collect records only GC starts and ends at very low cost, and gc-verbose adds allocation samples on top:

docker exec profseries-api dotnet-trace collect -p 1 --profile gc-verbose --duration 00:00:00:10 -o /tmp/export-gcv.nettrace

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x0000000000008003  Verbose(5)          --profile

The samples of gc-verbose are the GCAllocationTick event: roughly every 100 KB of allocation, the runtime writes the type and stack of the object that crossed the threshold. The 10-second trace came out at 317 MB. On Windows you can open the trace in PerfView's allocation stack views (06); I summarized it by type and by first Bookstore frame with a small TraceEvent script, and writing such a tool is also the topic of 06:

AllocationTick by type (events 167274, bytes 41.983.941.544)
   39,0%      681  System.String (Large)
   21,0%    83792  System.Char[] (Small)
   19,7%    79156  System.Text.StringBuilder (Small)
   19,5%      682  System.Byte[] (Large)
    0,4%     1584  System.IO.Pipelines.BufferSegment (Small)
AllocationTick by first Bookstore frame (events 167274, bytes 41.983.941.544)
   99,2%   164332  Bookstore.Api.Reports.ReportEndpoints+<>c.<MapReportEndpoints>b__1_1(class Bookstore.Api.Ordering.OrderStore)

99 percent of the allocations are in the export handler. The type breakdown confirms the code: the 24 MB string from csv.ToString() (12 MB of text takes twice as much in memory because it is UTF-16) and the 12 MB byte[] from GetBytes go straight to the LOH; StringBuilder keeps the text in 8,000-character chunks, and each chunk means a new char[] and a new StringBuilder object. In total: two large objects and thousands of small pieces per request.

Allocation Sampling in .NET 10

There is something odd in the table above: StringBuilder objects are small, around 48 bytes, yet 19.7 percent of the allocations are attributed to them. The reason is how AllocationTick works: it counts with a fixed start and a fixed stride, and whichever object crosses the threshold gets the whole 100 KB. Because the code allocates a StringBuilder right after every char[] chunk, the threshold often lands on it. The design document in dotnet/runtime describes this problem too: fixed-stride sampling can produce large errors on periodic allocation patterns.

The .NET 10 runtime brought a separate event for this: AllocationSampled. It is randomized sampling that gives each byte an independent probability; on average still about one sample per 100 KB, but with no fixed stride, and each sample yields a statistically sound estimate of total allocation. In dotnet-trace you enable it with the allocationsampling keyword:

docker exec profseries-api dotnet-trace collect -p 1 --clrevents gc+allocationsampling --duration 00:00:00:10 -o /tmp/export-as.nettrace

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x0000080000000001  Informational(4)    --clrevents

On runtime 10.0.15 the events arrived, and under the same load the 10-second trace came out at 18 MB, against 317 MB for gc-verbose. The breakdown I computed with the estimator from the design document (for each sample, size / (1 - q^size), with q = 1 - 1/102400):

AllocationSampling by type (events 173734, bytes 46.968.991.658)
   39,7%      775  System.String (Large)
   39,6%   168086  System.Char[] (Small)
   19,8%      775  System.Byte[] (Large)
    0,4%     1916  System.IO.Pipelines.BufferSegment (Small)
    0,1%      552  System.Text.StringBuilder (Small)
AllocationSampling by first Bookstore frame (events 173734, bytes 46.968.991.658)
   99,2%   170183  Bookstore.Api.Reports.ReportEndpoints+<>c.<MapReportEndpoints>b__1_1(class Bookstore.Api.Ordering.OrderStore)

StringBuilder objects dropped to 0.1 percent, and the char[] chunks rose to their real share (as much as the string, 24 MB). In 10 seconds 775 large strings were sampled; the probability of sampling a 24 MB object is nearly 1, so the string of each of the 775 requests in that window was caught. The estimated total is 47 GB, 4.7 GB per second, close to the 5.5 GB that counters measured (the request rate dropped a little while tracing). If you are going to take an allocation profile in production, try this first: it is both more accurate and a seventeen times smaller file.

The Fix: Streaming and ArrayPool<T>

There is no need to build the whole file in memory; streaming rows to the response as they are written is enough. I rent a single 64 KB buffer from ArrayPool<byte>, write the rows straight into it as UTF-8 and send it to the response when it fills up:

// streaming: one pooled 64 KB buffer, flushed to the response as it fills
app.MapGet("/api/reports/orders-v2.csv", async (HttpContext context, OrderStore orders) =>
{
    context.Response.ContentType = "text/csv";
    context.Response.Headers.ContentDisposition = "attachment; filename=orders.csv";

    byte[] buffer = ArrayPool<byte>.Shared.Rent(64 * 1024);
    try
    {
        int used = Encoding.UTF8.GetBytes(Header, buffer);
        foreach (Order order in orders.All)
        {
            int written;
            while (!Utf8.TryWrite(buffer.AsSpan(used), CultureInfo.InvariantCulture,
                $"{order.Id},{order.CustomerId},{order.PlacedAt:O},{order.Total},{order.Status}\n", out written))
            {
                await context.Response.Body.WriteAsync(buffer.AsMemory(0, used), context.RequestAborted);
                used = 0;
            }

            used += written;
        }

        await context.Response.Body.WriteAsync(buffer.AsMemory(0, used), context.RequestAborted);
    }
    finally
    {
        ArrayPool<byte>.Shared.Return(buffer);
    }
});

Utf8.TryWrite (added in .NET 8) writes an interpolated string straight into a byte span without creating an intermediate string; if there is not enough room it returns false, and I send the buffer and retry the same row. The 64 KB buffer is below the LOH threshold, but what really matters is not allocating a new one per request; returning the rented array in finally is a must, otherwise you get a new array each time instead of a pooled one. I checked with MD5 that both endpoints produce byte-for-byte identical output. Same load, each in a fresh container:

Allocation dropped 400 times and memory to a quarter; throughput, however, rose only 23 percent. The remaining limit is CPU: formatting 200,000 rows is work on every request, and 3.3 of the 4 CPUs are still in use. The GC problem is solved, the next bottleneck is formatting; you would see that with a CPU profile as in 03.

GC Modes and the Container Limit

The second guessing question was about settings. First you need to see what the runtime chose. I added a diagnostic endpoint to the lab that returns the GC settings:

// which GC mode and limits did the runtime pick?
app.MapGet("/diag/gc", () =>
{
    GCMemoryInfo info = GC.GetGCMemoryInfo();
    return Results.Ok(new
    {
        GCSettings.IsServerGC,
        LatencyMode = GCSettings.LatencyMode.ToString(),
        TotalAvailableMemoryMB = info.TotalAvailableMemoryBytes / 1024 / 1024,
        HeapSizeMB = info.HeapSizeBytes / 1024 / 1024,
        Config = GC.GetConfigurationVariables()
    });
});

{
    "isServerGC": true,
    "latencyMode": "Interactive",
    "totalAvailableMemoryMB": 1536,
    "config": {
        "ServerGC": true,
        "ConcurrentGC": true,
        "HeapCount": 4,
        "GCHeapHardLimit": 1610612736,
        "GCDynamicAdaptationMode": 1,
        "GCDTargetTCP": 2
    }
}

(I shortened the output.) Three things are visible. In ASP.NET Core projects the Web SDK turns ServerGarbageCollection on by default; that is why the build output's runtimeconfig.json has the "System.GC.Server": true line. DATAS has been on by default with Server GC since .NET 9 (GCDynamicAdaptationMode: 1); instead of keeping the number of heaps fixed it changes it with the load and tries to keep the heap close to the size of the long-lived data. Because I gave the container --memory 2g, the upper bound the GC can use for the heap (GCHeapHardLimit) is 1.5 GiB: in an environment with a limit, the default is 75 percent of the limit. A pod's memory limit in Kubernetes is read the same way; details in post 09 of the Kubernetes series.

I measured the same slow export in three modes, each time with a fresh container. I used environment variables to change the mode (DOTNET_gcServer=0, DOTNET_GCDynamicAdaptationMode=0):

Turning DATAS off halved the pause share but nearly doubled memory and did not raise throughput; Workstation GC got worse on every measure. The answer to the guess is "neither": no setting came close to what the fixed endpoint achieved with default settings (113 requests/s, 0.1 percent pause, 234 MB). GC settings are for fine-tuning after allocations are fixed; do not try to cover an allocation problem with a setting.

When you do need a setting, keeping it in the project is easier to track than an environment variable. MSBuild properties and runtimeconfig.template.json are written into runtimeconfig.json at build time:

<PropertyGroup>
  <GarbageCollectionAdaptationMode>0</GarbageCollectionAdaptationMode>
  <ConcurrentGarbageCollection>true</ConcurrentGarbageCollection>
</PropertyGroup>

{
  "configProperties": {
    "System.GC.HeapHardLimitPercent": 60
  }
}

"configProperties": {
  "System.GC.HeapHardLimitPercent": 60,
  "System.GC.Concurrent": true,
  "System.GC.Server": true,
  "System.GC.DynamicAdaptationMode": 0
}

In environment variables numbers are written in hexadecimal, in JSON in decimal; DOTNET_GCHeapHardLimitPercent=3C means 60 percent. These settings are read once when the process starts; changing them on a running process has no effect.

Working Set and the GC Heap Are Not the Same Thing

The tables above have three memory numbers, and they are all different. The GC heap is the live objects at the last GC plus the gaps between them. Committed is the memory the GC took from the operating system and holds on to; it is larger than the heap because the GC keeps room for upcoming allocations. The working set is all of the process's pages in physical memory: the GC's committed memory, code generated by the JIT, the runtime's own structures, native libraries, thread stacks. The OOM kill decision of Kubernetes and Docker looks at the container's total memory usage, not at the GC heap.

I saw the practical effect in one measurement: when I ran the slow export and then right afterwards the fixed version in the same container, the working set stayed at 685 MB and the LOH kept showing 158 MB. Since the fixed version never triggered a gen2, the GC had no reason to collect that memory and give it back to the operating system. In a fresh container the same endpoint ran at 234 MB. A working set that does not drop after the load ends is not proof of a leak on its own; you recognize a leak by the heap growing across repeated measurements (05).

In Production

For allocation profiles in production, the first choice is gc+allocationsampling: gc-verbose wrote more than 30 MB per second under this load. Whichever you take, keep it short and take it under the load where the problem happens; an allocation profile taken while idle shows you the cache filling at startup. For GC metrics, look at the distribution, not the average: the 568 pauses in the same trace average 4.2 ms, but p99 is 19 ms and the longest is 27 ms. If your p99 latency target is 50 ms, the real threat is not the average but those long pauses.

Think about the container memory limit and GC settings together. If you pull GCHeapHardLimit very close to the limit, there is no room left for native memory and code, and the OOM kill arrives before the GC reacts; if you pull it far down, the GC runs frequently and expensively, and you eventually see an OutOfMemoryException. The default 75 percent is reasonable for most services; measure the gap between the working set and committed memory before changing it.

Common Pitfalls

• "Fixing" it with GC.Collect(): memory drops for a moment, but the allocation rate does not change, and every call makes users pay for the pause of a full GC. Reduce the allocations.
• Looking only at the average pause; long pauses decide tail latency.
• Moving the problem by raising the LOH threshold (GCLOHThreshold): a 24 MB string is large at any threshold; the problem is not the object's size but allocating it again on every request.
• Not returning a buffer rented from ArrayPool, or keeping on using it after returning it; the latter is a hard-to-find bug that corrupts another request's data.
• Taking tables based on AllocationTick for an exact breakdown: in this case it showed StringBuilder 200 times bigger than it was.
• Raising a leak alarm because the working set does not drop after the load; first look at what the GC heap and the gen2 count are doing.

A Small Experiment

★☆☆ Call the lab's /diag/gc in two containers, one started with --memory 512m and one without a memory limit; see how GCHeapHardLimit and totalAvailableMemoryMB change.

★★☆ Find the endpoint that allocates the most in your own service with --clrevents gc+allocationsampling. Take a gc-verbose trace under the same load as well and compare whether the order of the top five types changes.

★★★ Rewrite orders-v2.csv to use context.Response.BodyWriter (a PipeWriter) with GetSpan/Advance; remove ArrayPool entirely. Measure allocation per request, p95 and CPU for both versions and explain where the difference comes from with a CPU profile.

In this post memory arrived quickly and left quickly. In the next post we look at memory that cannot leave: we will take and compare two heap snapshots with dotnet-gcdump, find handlers that subscribe to a singleton service and never unsubscribe through their retention paths, and prove the fix with a third snapshot.