Anatomia problemu CPU: od zaniżonego requestu do p99 latency

Krok 1: scheduler uwierzył requestowi

Node ma:

16 CPU

Na node działa 20 Podów.

Ich suma requestów:

10 CPU

Dla kube-schedulera sytuacja wygląda zdrowo:

requested capacity = 10 CPU
node capacity      = 16 CPU

Nasz serwis deklaruje:

500m

więc scheduler traktuje każdą jego replikę jako workload potrzebujący pół CPU.

Problem w tym, że przy peak traffic realny demand jednej repliki nie wynosi już:

500m

tylko na przykład:

1.5 CPU

Request nie ogranicza workloadu, więc aplikacja może próbować użyć więcej.

Ale scheduler podczas placementu nie wiedział, że kilka workloadów jednocześnie będzie potrzebować znacznie więcej niż deklarowały.

Krok 2: realny demand przekracza capacity

W czasie normalnego ruchu node wygląda tak:

capacity = 16 CPU
demand   = 8 CPU

Dużo wolnej mocy.

Podczas peak:

API pods      -> 10 CPU
batch jobs    -> 4 CPU
inne serwisy  -> 7 CPU

Łącznie:

demand = 21 CPU

na:

capacity = 16 CPU

Brakuje:

5 CPU

Linux nie może wykonać 21 CPU pracy równolegle na 16 logical CPUs.

Nie istnieje żadna ukryta rezerwa.

Część tasków musi czekać.

Krok 3: nie ma throttlingu

Nasz Pod nie posiada:

limits:
  cpu:

czyli nie ma skończonego CPU bandwidth limitu.

W cgroup v2 będzie to odpowiadać sytuacji typu:

cpu.max = max ...

Sprawdzamy cpu.stat.

Nie obserwujemy rosnącego:

nr_throttled

Wniosek:

kernel nie zatrzymuje aplikacji
z powodu wyczerpania quota

To ważne.

Gdybyśmy w tym momencie automatycznie zwiększyli CPU limit, niczego byśmy nie naprawili.

Limitu przecież nie ma.

Problem znajduje się gdzie indziej.

Krok 4: task staje się runnable

Przychodzi request HTTP.

Worker aplikacji dostaje pracę:

request
   |
   v
thread becomes runnable

Normalnie scheduler bardzo szybko daje mu CPU:

runnable
   |
   v
running

Załóżmy, że obsługa requestu potrzebuje łącznie:

6 ms CPU time

Na zdrowym node wykonanie może wyglądać tak:

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

Latency CPU-related:

~6 ms

Podczas contention sytuacja wygląda inaczej.

Krok 5: runnable nie oznacza running

Node ma dużo konkurujących tasków.

Nasz thread staje się runnable:

t = 0 ms

ale scheduler nie daje mu CPU od razu.

Dostajemy:

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

Potem thread wykonuje:

8 ms -> 10 ms

czyli:

2 ms CPU time

Następuje kolejne przełączenie.

Thread ponownie czeka:

10 ms -> 17 ms

Potem wykonuje kolejną porcję pracy.

Całość może wyglądać tak:

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

CPU time aplikacji:

6 ms

Wall-clock time:

21 ms

Kod aplikacji nie stał się trzy razy droższy.

Po prostu wykonanie tych samych 6 ms CPU zostało rozciągnięte przez scheduler wait.

Krok 6: CPU usage nie pokazuje brakującego czasu

To najważniejszy moment całego incydentu.

Monitoring pokazuje:

Pod CPU usage = 900m

Można pomyśleć:

przecież nawet nie używa całego CPU

Ale usage mówi:

ile CPU time workload faktycznie dostał

Nie mówi:

ile CPU workload chciał dostać

Jeżeli aplikacja chciała średnio:

1.5 CPU

ale przez contention otrzymywała:

0.9 CPU

metryka usage pokaże:

0.9 CPU

Brakujące:

0.6 CPU

nie pojawi się jako usage.

To niewykonana praca czekająca na scheduler.

Krok 7: PSI pokazuje pressure

Patrzymy na CPU PSI.

Przed incydentem:

some avg10=1.20

Podczas problemu:

some avg10=34.00

To zupełnie inna informacja niż:

CPU usage = 900m

PSI mówi nam, że przez znaczną część czasu runnable work doświadcza CPU stall.

Czyli:

aplikacja chce się wykonywać
+
scheduler nie może od razu dać jej CPU

Mamy już mocny dowód na:

CPU contention

Krok 8: runqueue latency potwierdza mechanizm

Jeżeli potrzebujemy dokładniejszego potwierdzenia, patrzymy na moment:

sched_wakeup

oraz:

sched_switch

Przykład:

thread runnable:
14:00:00.100

thread running:
14:00:00.108

Scheduler delay:

8 ms

Dla requestu HTTP, którego własna praca CPU wynosi kilka milisekund, dodatkowe:

5-10 ms

oczekiwania przy wielu kolejnych wakeupach może dramatycznie zwiększyć końcową latency.

Dlaczego szczególnie rośnie p99

Nie każdy request trafia na identyczną sytuację.

Jeden request może dostać CPU niemal natychmiast:

scheduler wait = 0.2 ms

Inny:

scheduler wait = 3 ms

Jeszcze inny trafia w najgorszy moment:

scheduler wait = 15 ms

Średnia latency może więc wzrosnąć umiarkowanie.

Ale tail:

p95
p99
p99.9

zaczyna rosnąć dużo szybciej.

Przykład:

before:

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

podczas contention:

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

To typowy charakter problemów kolejkowych.

Im bardziej przeciążony jest zasób, tym bardziej nierówny staje się czas oczekiwania poszczególnych requestów.

Gdzie w tym wszystkim był request CPU

Wracamy do początku:

requests:
  cpu: 500m

Request nie spowodował bezpośrednio:

p99 = 180 ms

Ale wpłynął na dwa istotne elementy systemu.

Placement

Scheduler policzył workload jako:

0.5 CPU

Jeżeli realny steady-state albo peak demand był znacznie większy, node mógł zostać zapełniony bardziej agresywnie, niż sugerowała rzeczywista charakterystyka workloadów.

CPU weight

Pod contention request wpływa również na względną wagę workloadu.

Zaniżony request może więc oznaczać:

agresywniejszy placement
+
słabszą pozycję podczas konkurencji

To nie jest gwarancja problemu.

Ale oba efekty działają w niekorzystnym kierunku, kiedy CPU zaczyna brakować.

Noisy neighbor może uruchomić cały incydent

Załóżmy, że API samo się nie zmieniło.

Problem zaczyna się o 14:00, ponieważ na tym samym node batch workload przechodzi z:

200m

do:

6 CPU

Batch nie ma limitu.

Ma wolne prawo próbować wykorzystać dostępne CPU.

Przed 14:00:

node demand < capacity

Po 14:00:

node demand > capacity

API zaczyna czekać w runqueue.

Z jego punktu widzenia:

kod ten sam
traffic podobny
CPU usage podobne
p99 eksploduje

Problem nie znajduje się wyłącznie „wewnątrz Poda”.

Znajduje się we współdzielonym zasobie.

Jak wygląda pełna diagnoza

Mamy symptom:

p99 latency ↑

Sprawdzamy usage:

CPU usage = 900m

Nie wystarcza do diagnozy.

Sprawdzamy limit:

brak

Sprawdzamy throttling:

nr_throttled nie rośnie

Czyli:

to nie quota

Sprawdzamy PSI:

CPU pressure ↑

Czyli:

runnable work czeka

Sprawdzamy node:

inne workloady burstują

Sprawdzamy scheduler latency:

runnable -> running delay ↑

Diagnoza:

CPU contention
spowodowany przeciążeniem wspólnego node'a

Nie:

CPU limit jest za niski

Nie:

aplikacja nagle zużywa więcej instrukcji

Nie:

900m CPU to za dużo

Tylko konkretny mechanizm.

Cała ścieżka

Incydent można sprowadzić do:

zaniżone / agresywne requests
        |
        v
gęsty bin packing
        |
        v
równoczesny burst workloadów
        |
        v
CPU demand > CPU capacity
        |
        v
więcej runnable tasks niż dostępnego CPU
        |
        v
runqueue
        |
        v
scheduler latency
        |
        v
request execution rozciągnięte w czasie
        |
        v
p99 latency ↑

A obserwowalność tej samej ścieżki:

CPU usage
    |
    | nie pokazuje całego demand
    v
cpu.stat
    |
    | brak throttlingu
    v
CPU PSI
    |
    | pressure rośnie
    v
scheduler / runqueue latency
    |
    v
potwierdzone CPU contention

To jest najważniejszy wniosek całej serii:

"problem z CPU"

nie jest jedną rzeczą.

Może oznaczać:

za mało CPU capacity
zły request
CPU throttling
CPU contention
noisy neighbor
zły placement na hardware

Dlatego debugowanie CPU zaczyna się nie od pytania:

ile procent CPU widzę?

ale od:

czy workload dostał CPU wtedy,
kiedy chciał wykonać pracę?

Jeżeli nie - kolejne pytanie brzmi:

co dokładnie mu w tym przeszkodziło?

I dopiero wtedy mamy diagnozę.