Slow but not busy: diagnosing a .NET API from its logs

The API is slow and some requests are failing. Someone with cluster access has checked the pod and says CPU and memory look normal. You don't have production access. There's no tracing, no dashboards, no Application Insights. What you have is the application's logs, the lines your code writes when it starts and finishes doing things.

That's less than you'd like, but it's usually enough. Start from the clue you've already been given: if the pod isn't busy, your API isn't doing too much work. It's waiting, for a thread, a connection, a lock or another service. The logs can tell you which one.

#Get the logs into a file

However your team gets logs to you (a kubectl logs export, a download from a log viewer, a file someone sends you), get a copy that covers the time before the problem started and the time during it. Working from a file means you can search and count without waiting on anyone.

Two quick counts are worth doing first:

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

# Did the app restart? Each startup logs this line.
grep -c "Now listening on" api.log

If that second number is more than one, the pod is restarting, and that changes the story (more on that below).

#Read the gaps, not the lines

Your log lines have timestamps. The time between two lines for the same request is where that request spent its time. Pick a few slow requests and line up their log entries. A correlation ID makes this easy; if you don't have one, the request path and thread or trace fields usually get you close enough.

There are two patterns to look for.

One big gap, always in the same place. Everything is quick except the step that calls something else:

14:02:11.104 [7f3a] GET /orders/123 received
14:02:11.106 [7f3a] Loading order from database
14:02:14.981 [7f3a] Order loaded
14:02:14.983 [7f3a] Calling pricing API
14:02:15.120 [7f3a] Pricing returned

Four seconds disappeared around the database call. The problem is the database, or getting a connection to it.

Gaps everywhere, even around trivial code. Steps that should take a millisecond take hundreds:

14:02:11.104 [7f3a] GET /orders/123 received
14:02:11.912 [7f3a] Request validated
14:02:12.687 [7f3a] Loading order from database
14:02:12.701 [7f3a] Order loaded
14:02:13.540 [7f3a] Calling pricing API

The database call itself was fast. The time went to waiting in between, after each await, for a thread to pick the request back up. That's thread pool starvation, and it's the classic cause of "slow but not busy."

#What the logs are telling you

That Kestrel warning is worth searching for by name. ASP.NET Core logs it at Warning level, so it's usually in your logs even when the framework's Information messages are switched off.

#Kubernetes makes two of these worse

Two things about running in a pod can turn a small problem into an outage, and both hide from "CPU looks normal."

CPU limits set the size of the thread pool. .NET reads the container's CPU limit and treats it as the number of processors. With a limit of 1 CPU, the thread pool starts with very few threads and adds more slowly, about one a second. A few blocking calls (.Result, .Wait(), GetAwaiter().GetResult()) are enough to tie them all up. The limit also throttles the container in short bursts, which an average CPU figure smooths over.

Liveness probes fail when the API is starved. If the health check endpoint is stuck in the same queue as everything else, Kubernetes decides the pod is dead and restarts it. The restart clears the queue, things look fine for a while, and then it happens again. That's what repeated "Now listening on" lines usually mean.

You probably can't see the cluster, but you can often read the deployment files. Check the Helm chart or manifests in your repo for resources.limits.cpu and the liveness probe settings. Then ask the person with access for three things: kubectl describe pod (restart count and the reason), kubectl logs --previous (the logs from before the last restart), and whether the container is being CPU throttled.

#Reproduce it where you do have access

Once the logs point at a cause, prove it somewhere you control. Run the same image locally with the same limits as production:

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

Put some load on it with a tool like k6 or bombardier, and watch it with dotnet-counters from inside the container. If threadpool-queue-length climbs while CPU stays low, you've reproduced it. Then search the code for what the logs pointed at: blocking calls on async code, new HttpClient() in a using block (see Stop newing up HttpClient), database connections that aren't disposed, or outbound calls without a timeout.

#Log what you'll need next time

You can make the next incident much shorter with a couple of small changes.

Turn on ASP.NET Core's own request logging by setting Microsoft.AspNetCore.Hosting.Diagnostics to Information. Every request then logs a "Request finished" line with its duration, so you can see which endpoints are slow without adding anything.

And log the thread pool's numbers yourself, since you can't watch the counters in production:

public sealed class ThreadPoolLogger(ILogger<ThreadPoolLogger> logger) : BackgroundService
{
    private static readonly TimeSpan Interval = TimeSpan.FromSeconds(10);

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        using var timer = new PeriodicTimer(Interval);
        var last = Stopwatch.GetTimestamp();

        while (await timer.WaitForNextTickAsync(stoppingToken))
        {
            var lag = Stopwatch.GetElapsedTime(last) - Interval;
            last = Stopwatch.GetTimestamp();

            logger.LogInformation(
                "Thread pool: {Threads} threads, {Queued} queued, timer lag {LagMs} ms",
                ThreadPool.ThreadCount,
                ThreadPool.PendingWorkItemCount,
                (int)lag.TotalMilliseconds);
        }
    }
}

Register it with builder.Services.AddHostedService<ThreadPoolLogger>();. The lag is the useful part: the timer runs on the thread pool too, so when the pool is starved, this line shows up late, and the lag says by how much.

#Takeaway

When an API is slow but not busy, it's waiting on something, and the gaps between your log lines show you where. One gap around one call points at that dependency. Gaps everywhere point at thread pool starvation, which a CPU limit in Kubernetes makes much easier to hit. Reproduce it with the same limits somewhere you control, and add the logging that would have made it obvious.