Anatomy of a CPU problem: from an understated request to p99 latency

Step 1: the scheduler believed the request

The node has:

16 CPU

There are 20 Pods running on it.

The sum of their requests:

10 CPU

For kube-scheduler the situation looks healthy:

requested capacity = 10 CPU
node capacity      = 16 CPU

Our service declares:

500m

so the scheduler treats each of its replicas as a workload needing half a CPU.

The trouble is that under peak traffic the real demand of a single replica is no longer:

500m

but, say:

1.5 CPU

A request does not cap the workload, so the application may try to use more.

But during placement the scheduler did not know that several workloads would simultaneously need far more than they declared.

Step 2: real demand exceeds capacity

During normal traffic the node looks like this:

capacity = 16 CPU
demand   = 8 CPU

Plenty of spare power.

During the peak:

API pods       -> 10 CPU
batch jobs     -> 4 CPU
other services -> 7 CPU

In total:

demand = 21 CPU

on:

capacity = 16 CPU

We are short of:

5 CPU

Linux cannot execute 21 CPU of work in parallel on 16 logical CPUs.

There is no hidden reserve.

Some tasks have to wait.

Step 3: there is no throttling

Our Pod does not have:

limits:
  cpu:

so it has no finite CPU bandwidth limit.

In cgroup v2 that corresponds to a situation like:

cpu.max = max ...

We check cpu.stat.

We do not observe a growing:

nr_throttled

Conclusion:

the kernel is not stopping the application
because of exhausted quota

That matters.

If at this point we automatically raised the CPU limit, we would fix nothing.

There is no limit, after all.

The problem is somewhere else.

Step 4: the task becomes runnable

An HTTP request arrives.

The application's worker gets work:

request
   |
   v
thread becomes runnable

Normally the scheduler gives it a CPU very quickly:

runnable
   |
   v
running

Assume handling the request needs a total of:

6 ms CPU time

On a healthy node the execution may look like this:

0 ms             6 ms
|-----------------|
      running

CPU-related latency:

~6 ms

Under contention the situation looks different.

Step 5: runnable does not mean running

The node has many competing tasks.

Our thread becomes runnable:

t = 0 ms

but the scheduler does not give it a CPU right away.

We get:

0 ms       8 ms
|-----------|
 runnable
 waiting

Then the thread executes:

8 ms -> 10 ms

that is:

2 ms CPU time

Another switch happens.

The thread waits again:

10 ms -> 17 ms

Then it executes another slice of work.

The whole thing may look like this:

0------8--10-------17----21
| WAIT |RUN| WAIT  | RUN |

The application's CPU time:

6 ms

Wall-clock time:

21 ms

The application's code did not become three times more expensive.

Executing the same 6 ms of CPU was simply stretched out by scheduler wait.

Step 6: CPU usage does not show the missing time

This is the most important moment of the whole incident.

Monitoring shows:

Pod CPU usage = 900m

You might think:

it is not even using a whole CPU

But usage says:

how much CPU time the workload actually got

It does not say:

how much CPU the workload wanted

If the application wanted on average:

1.5 CPU

but through contention received:

0.9 CPU

the usage metric will show:

0.9 CPU

The missing:

0.6 CPU

will not appear as usage.

It is work not done, waiting for the scheduler.

Step 7: PSI shows the pressure

We look at CPU PSI.

Before the incident:

some avg10=1.20

During the problem:

some avg10=34.00

That is completely different information from:

CPU usage = 900m

PSI tells us that for a significant part of the time runnable work is experiencing CPU stall.

That is:

the application wants to execute
+
the scheduler cannot give it CPU right away

We already have strong evidence for:

CPU contention

Step 8: runqueue latency confirms the mechanism

If we need a more precise confirmation, we look at the moment of:

sched_wakeup

and:

sched_switch

Example:

thread runnable:
14:00:00.100

thread running:
14:00:00.108

Scheduler delay:

8 ms

For an HTTP request whose own CPU work is a few milliseconds, an extra:

5-10 ms

of waiting across many consecutive wakeups can increase the final latency dramatically.

Why p99 in particular goes up

Not every request hits the same situation.

One request may get a CPU almost immediately:

scheduler wait = 0.2 ms

Another:

scheduler wait = 3 ms

Yet another hits the worst possible moment:

scheduler wait = 15 ms

So average latency may rise moderately.

But the tail:

p95
p99
p99.9

starts rising much faster.

Example:

before:

p50 = 15 ms
p95 = 25 ms
p99 = 35 ms

during contention:

p50 = 22 ms
p95 = 80 ms
p99 = 180 ms

That is the typical character of queueing problems.

The more overloaded a resource is, the more uneven the waiting time of individual requests becomes.

Where was the CPU request in all this

Back to the beginning:

requests:
  cpu: 500m

The request did not directly cause:

p99 = 180 ms

But it influenced two important elements of the system.

Placement

The scheduler counted the workload as:

0.5 CPU

If the real steady-state or peak demand was much larger, the node may have been filled more aggressively than the actual characteristics of the workloads suggested.

CPU weight

Under contention a request also influences the workload's relative weight.

An understated request may therefore mean:

more aggressive placement
+
a weaker position during competition

That is not a guarantee of a problem.

But both effects work in an unfavourable direction once CPU starts running short.

A noisy neighbor can trigger the whole incident

Assume the API itself did not change.

The problem starts at 14:00 because on the same node a batch workload goes from:

200m

to:

6 CPU

Batch has no limit.

It is perfectly entitled to try to use the available CPU.

Before 14:00:

node demand < capacity

After 14:00:

node demand > capacity

The API starts waiting in the runqueue.

From its point of view:

same code
similar traffic
similar CPU usage
p99 explodes

The problem does not live only "inside the Pod".

It lives in the shared resource.

What the full diagnosis looks like

We have the symptom:

p99 latency up

We check usage:

CPU usage = 900m

Not enough for a diagnosis.

We check the limit:

none

We check throttling:

nr_throttled is not growing

So:

this is not quota

We check PSI:

CPU pressure up

So:

runnable work is waiting

We check the node:

other workloads are bursting

We check scheduler latency:

runnable -> running delay up

Diagnosis:

CPU contention
caused by overloading the shared node

Not:

the CPU limit is too low

Not:

the application suddenly executes more instructions

Not:

900m CPU is too much

Just a specific mechanism.

The whole path

The incident can be reduced to:

understated / aggressive requests
        |
        v
dense bin packing
        |
        v
simultaneous burst of workloads
        |
        v
CPU demand > CPU capacity
        |
        v
more runnable tasks than available CPU
        |
        v
runqueue
        |
        v
scheduler latency
        |
        v
request execution stretched over time
        |
        v
p99 latency up

And the observability of that same path:

CPU usage
    |
    | does not show the whole demand
    v
cpu.stat
    |
    | no throttling
    v
CPU PSI
    |
    | pressure rises
    v
scheduler / runqueue latency
    |
    v
confirmed CPU contention

This is the most important conclusion of the whole series:

"a CPU problem"

is not one thing.

It may mean:

too little CPU capacity
a bad request
CPU throttling
CPU contention
a noisy neighbor
bad placement on the hardware

That is why debugging CPU does not start with the question:

what percentage of CPU do I see?

but with:

did the workload get CPU when
it wanted to do work?

If not, the next question is:

what exactly prevented it?

And only then do we have a diagnosis.