Slow and busy: diagnosing a .NET API that's running hot

Last week the API was slow, but the pod was quiet: CPU and memory looked normal, so the API was waiting on something. This week it's the opposite. Someone with cluster access checks the pod and says CPU is pegged, or memory keeps climbing, or both. You still don't have production access, and you still only have the application's logs.

The clue points the other way now. If the pod is busy, your API isn't waiting. It's doing too much work or holding on to too much memory, and often both, because one tends to cause the other. The logs won't show you a CPU graph, but they can tell you which of those it is and roughly where to look.

#Ask one follow-up question first

"Memory is high" can mean two different problems, so ask the person who saw it which one they mean:

• It climbs steadily for hours and never comes back down. That's a leak: something is keeping objects alive.
• It jumps at certain moments and then falls back. That's a big allocation: some request is loading far more into memory than it should.

For CPU, ask whether it's high all the time or in bursts. Constant high CPU points at something that runs on every request, or at the garbage collector. Bursts point at particular requests or background jobs.

#Get the logs into a file

Same as last time: get a copy covering the time before the problem and during it, so you can search and count it yourself. Then do the same quick counts, plus one more:

# Which exceptions are showing up, and how often?
grep -oE "[A-Za-z.]+Exception" api.log | sort | uniq -c | sort -rn

# How many times did the app start, and how many times did it shut down cleanly?
grep -c "Now listening on" api.log
grep -c "Application is shutting down" api.log

# How many log lines per minute? (Assumes each line starts with HH:MM:SS)
cut -c1-5 api.log | sort | uniq -c

The second pair of numbers matters more than it looks. When Kubernetes restarts a pod politely, for a deployment or a failed liveness probe, it sends a stop signal first, and ASP.NET Core logs "Application is shutting down..." on the way out. When the container runs out of memory, it's killed on the spot and logs nothing. So if the app started five times but only shut down cleanly once, the other restarts were probably the container being killed for using too much memory.

The last count is useful for CPU problems. If the number of lines per minute jumps by ten times when the trouble starts, something is running in a tight loop, and the logging itself may be a big part of the cost.

#Read the shape over time

Last week the useful thing was the gaps between lines inside one request. This week it's how things change across many requests over hours. ASP.NET Core's "Request finished" lines, with a duration on the end, are ideal for this (see the end of this post for how to turn them on).

Everything slows down gradually, then resets. The same cheap request gets slower over the afternoon, the app restarts, and it's fast again:

09:00:12 Request finished GET /orders/123 - 200 - 41ms
11:30:05 Request finished GET /orders/123 - 200 - 96ms
14:10:47 Request finished GET /orders/123 - 200 - 380ms
15:52:31 Request finished GET /orders/123 - 200 - 1840ms
15:58:02 Now listening on: http://[::]:8080
16:00:15 Request finished GET /orders/123 - 200 - 39ms

That's a memory leak. As memory fills up, the garbage collector runs more and more often trying to free space, which is where the CPU goes, and every request pays for it. Eventually the container hits its memory limit and gets killed. If the restarts happen at roughly regular intervals, that's almost a signature.

One endpoint is slow, and it's slow in proportion to its input. Small requests are fine; big ones take much longer than they should:

10:14:02 Request finished POST /imports - 200 - 120ms   (rows: 500)
10:21:40 Request finished POST /imports - 200 - 470ms   (rows: 1000)
10:33:19 Request finished POST /imports - 200 - 7900ms  (rows: 4000)

Twice the rows, four times the time. That's code doing work that grows faster than its input, usually a lookup inside a loop (list.Contains, list.First(x => ...), a LINQ query re-run on every iteration). Logging a size alongside the duration, as above, is what makes this visible.

The same warning or exception, thousands of times a minute. Exceptions are expensive to throw, and more expensive to log with their stack traces:

14:02:11.104 warn: Call to inventory API failed, retrying (attempt 1)
14:02:11.106 warn: Call to inventory API failed, retrying (attempt 2)
14:02:11.109 warn: Call to inventory API failed, retrying (attempt 3)

Retries three milliseconds apart mean there's no delay between attempts. A dependency goes down and every request turns into a loop that burns CPU. That's what backoff and jitter are for.

#What the logs are telling you

#Where the memory usually goes

When the logs say "leak," these are the usual suspects in a .NET API. They're all worth a search through the code:

• A static dictionary or list that only grows. A "cache" someone added by hand, keyed by something unbounded like a user ID or a URL, with nothing that ever removes entries.
• IMemoryCache with no size limit, especially with keys built from user input. Set SizeLimit and give entries a Size and an expiration.
• A singleton holding something scoped. A DbContext captured by a singleton keeps every entity it ever loaded in its change tracker. See DI lifetimes and captive dependencies.
• Event handlers that are never removed. Subscribing a short-lived object to a long-lived object's event keeps the short-lived one alive forever.
• new XmlSerializer(type, root) (or any constructor other than new XmlSerializer(type)) inside a method. Each call generates a new assembly that is never unloaded. Create it once and keep it.

For the "jumps" kind, look for ToListAsync() on a query with no filter or paging, ReadToEndAsync() on a large request or file, and MemoryStream used to buffer things that could be streamed instead.

#Kubernetes makes two of these worse

Last week it was the CPU limit and the liveness probe. They're still involved, but the memory limit matters just as much here.

The memory limit sets the size of the heap. .NET reads the container's memory limit and, by default, allows its heap to use up to 75% of it. As the heap gets close to that line, the garbage collector runs again and again trying to stay under it. That's why a leak in a container so often shows up as high CPU before it shows up as a crash: the collector is working flat out. If the heap does reach its limit, you get an OutOfMemoryException in the logs. If memory outside the heap (native libraries, buffers, thread stacks) pushes the whole container over its limit first, Kubernetes kills it and you get no log line at all.

A busy pod fails its liveness probe too. When CPU is at the limit, the container is throttled, and the health check endpoint waits in line with everything else. Kubernetes restarts the pod, the restart briefly hides the problem, and the loop starts again. That's the same pattern as last week, from the opposite cause.

From the repo, check the Helm chart or manifests for resources.limits.memory and resources.limits.cpu. Then ask the person with access for kubectl describe pod. Under Last State, a reason of OOMKilled (exit code 137) confirms the memory kill. Ask for kubectl logs --previous as well, for the logs from just before the last restart, and kubectl top pod while the problem is happening.

#Reproduce it where you do have access

Run the same image locally with the same limits as production:

docker run --cpus=1 --memory=512m -p 8080:8080 your-api:latest

Put load on the endpoints the logs pointed at, and watch it with dotnet-counters from inside the container. The counters to watch are different from last week:

• cpu-usage and time-in-gc: if a large share of CPU time is spent in garbage collection, it's a memory problem, not a CPU problem.
• gc-heap-size and working-set: a leak climbs and never comes down, even after the load stops.
• gen-2-gc-count: frequent full collections mean the collector is struggling.
• exception-count: confirms an exception storm.

Then take a closer look. For CPU, dotnet-trace collect -p <pid> records where the time goes. For memory, take two heap snapshots with dotnet-gcdump collect -p <pid>, a few minutes of load apart, and compare them in Visual Studio. Whatever type has grown between the two snapshots is your leak, and the tool shows you what's holding on to it.

#Log what you'll need next time

Turn on the "Request finished" lines by setting Microsoft.AspNetCore.Hosting.Diagnostics to Information, and log the size of anything that varies (rows, items, bytes) on the endpoints that do real work.

Then log the runtime's own numbers, since you can't watch the counters in production. This is the memory-and-CPU partner to last week's thread pool logger:

public sealed class RuntimeLogger(ILogger<RuntimeLogger> logger) : BackgroundService
{
    private static readonly TimeSpan Interval = TimeSpan.FromSeconds(30);
    private static long _exceptions;

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        AppDomain.CurrentDomain.FirstChanceException +=
            (_, _) => Interlocked.Increment(ref _exceptions);

        using var process = Process.GetCurrentProcess();
        using var timer = new PeriodicTimer(Interval);

        var lastCpu = process.TotalProcessorTime;
        var lastPause = GC.GetTotalPauseDuration();
        var lastGen2 = GC.CollectionCount(2);

        while (await timer.WaitForNextTickAsync(stoppingToken))
        {
            process.Refresh();
            var cpu = process.TotalProcessorTime;
            var pause = GC.GetTotalPauseDuration();
            var gen2 = GC.CollectionCount(2);
            var gc = GC.GetGCMemoryInfo();

            logger.LogInformation(
                "Runtime: CPU {CpuPercent:F0}%, working set {WorkingSetMb} MB, " +
                "heap {HeapMb} MB of {HeapLimitMb} MB, gen 2 GCs {Gen2}, " +
                "GC pauses {PauseMs} ms, exceptions {Exceptions}",
                (cpu - lastCpu) / Interval / Environment.ProcessorCount * 100,
                process.WorkingSet64 / 1_048_576,
                gc.HeapSizeBytes / 1_048_576,
                gc.TotalAvailableMemoryBytes / 1_048_576,
                gen2 - lastGen2,
                (int)(pause - lastPause).TotalMilliseconds,
                Interlocked.Exchange(ref _exceptions, 0));

            lastCpu = cpu;
            lastPause = pause;
            lastGen2 = gen2;
        }
    }
}

Register it with builder.Services.AddHostedService<RuntimeLogger>();. Every 30 seconds you get one line with CPU as a percentage of the container's limit (Environment.ProcessorCount already accounts for it), how much memory the process and the heap are using, how close the heap is to its limit, how hard the garbage collector worked, and how many exceptions were thrown, including the ones your code caught and swallowed. A leak shows up as the heap number creeping toward the limit while the GC numbers climb. And because these lines are written right up to the end, the last one before an unexplained restart tells you how full memory was when the container was killed.

#Takeaway

When an API is slow and busy, it's doing too much work or holding too much memory, and in a container the second usually causes the first. Count restarts against clean shutdowns to spot memory kills, watch request durations over hours for leaks, and compare durations to input sizes for hot loops. Reproduce it with the same limits somewhere you control, use a heap snapshot or a trace to find the exact cause, and add the runtime logging that would have made it obvious.