Go p99 Latency Špičky: Vnorené context.WithTimeout Timer Búrky

Timery su zadarmo, kym ich nemas miliony. Každých 30 sekúnd nám vystrelilo p99. Samozrejme, prvým podozrivým bola sieť. Spoiler: sieť bola nevinná.

Skutočný problém bol v middleware: každá vrstva si „pre istotu“ nastavila vlastný context.WithTimeout—HTTP server, auth, service client, databázový driver. Štyri vrstvy znamenajú štyri timery na request. Pri 10k RPS je to ~40 000 timerov za sekundu, tlak na Go runtime timer heap a viac práce pre GC.

V tomto článku ukážem, ako tento vzor spoznať, prečo sa deje a ako dnes timeouty skladám tak, aby chránili systém bez toho, aby vytvárali timer búrku.

Prostredie: Go 1.21, vysokopriepustná HTTP služba, 10k RPS

Problém

Symptómy

// Latency vzor:
// p50: 5ms (stabilné)
// p95: 15ms (stabilné)
// p99: 50ms normálne, ale špičky na 500ms každých 30 sekúnd

// CPU a pamäť vyzerajú normálne
// Network latency je stabilná
// Žiadny zjavný bottleneck

Skrytá Timer Explózia

// Bežný vzor - vyzerá nevinne:
func handleRequest(w http.ResponseWriter, r *http.Request) {
    // Vrstva 1: HTTP server timeout
    ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second)
    defer cancel()

    // Vrstva 2: Service call timeout
    ctx2, cancel2 := context.WithTimeout(ctx, 10*time.Second)
    defer cancel2()

    result, err := callExternalService(ctx2)
    // ...
}

func callExternalService(ctx context.Context) (Result, error) {
    // Vrstva 3: gRPC client timeout
    ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
    defer cancel()

    // Vrstva 4: Individuálny RPC timeout
    ctx2, cancel2 := context.WithTimeout(ctx, 2*time.Second)
    defer cancel2()

    return client.Call(ctx2)
}

// Pri 10k RPS, toto vytvára:
// 10,000 × 4 timerov = 40,000 timerov ZA SEKUNDU

// Timery žijú celú svoju duration aj keď:
// - Request skončí skôr
// - Context je zrušený
// Do Go 1.23, čistenie timerov bolo oneskorené!

Príčina

Ako context.WithTimeout Vytvára Timery

// Každý WithTimeout vytvára timer:
func WithTimeout(parent Context, timeout time.Duration) (Context, CancelFunc) {
    return WithDeadline(parent, time.Now().Add(timeout))
}

func WithDeadline(parent Context, d time.Time) (Context, CancelFunc) {
    // ...
    c := &timerCtx{...}
    // TOTO VYTVÁRA RUNTIME TIMER
    c.timer = time.AfterFunc(dur, func() {
        c.cancel(true, DeadlineExceeded, cause)
    })
    return c, func() { c.cancel(true, Canceled, nil) }
}

// Timer je pridaný do globálneho timer heap
// Timer heap operácie sú O(log n)
// So 40,000 timermi, každá operácia je pomalšia

Timer Heap Pod Tlakom

Timer heap pod tlakom:

Normálne (málo timerov):
┌────────────────────────────┐
│ Timer Heap (100 timerov)   │
│ Insert: O(log 100) = rýchle│
│ Pop: O(log 100) = rýchle   │
└────────────────────────────┘

Pod záťažou (veľa timerov):
┌────────────────────────────┐
│ Timer Heap (40,000 timerov)│
│ Insert: O(log 40000) = 15x │
│ Pop: O(log 40000) = 15x    │
│ GC scan: skenuje 40k ptr   │
└────────────────────────────┘

Každý timer je goroutine čakajúca
GC musí skenovať všetky
Timer operácie držia locky
Výsledok: periodické latency špičky

Riešenie

Možnosť 1: Použi Jednu Propagovanú Deadline

// PRED: Vnorené timeouty
func handleRequest(w http.ResponseWriter, r *http.Request) {
    ctx1, cancel1 := context.WithTimeout(r.Context(), 30*time.Second)
    defer cancel1()

    ctx2, cancel2 := context.WithTimeout(ctx1, 10*time.Second)
    defer cancel2()

    callService(ctx2) // vytvára viac timeoutov vnútri
}

// PO: Jedna deadline, propagovaná
func handleRequest(w http.ResponseWriter, r *http.Request) {
    // Jeden timeout na okraji
    ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second)
    defer cancel()

    // Pošli ďalej bez nových timerov
    callService(ctx)
}

func callService(ctx context.Context) {
    // Nepridávaj ďalší timeout - rodič už má deadline
    // Len skontroluj či deadline existuje
    if _, ok := ctx.Deadline(); !ok {
        // Pridaj timeout len ak žiadny neexistuje
        var cancel context.CancelFunc
        ctx, cancel = context.WithTimeout(ctx, 10*time.Second)
        defer cancel()
    }

    // Použi existujúcu deadline
    client.Call(ctx)
}

Možnosť 2: Použi Deadline Namiesto Timeout

// PRED: Viacero WithTimeout volaní
ctx1, _ := context.WithTimeout(ctx, 30*time.Second)
ctx2, _ := context.WithTimeout(ctx1, 10*time.Second)
ctx3, _ := context.WithTimeout(ctx2, 5*time.Second)
// Vytvára 3 timery, všetky sledujú rovnaký request

// PO: Vypočítaj a použi jednu deadline
deadline := time.Now().Add(5 * time.Second) // najmenší timeout
ctx, cancel := context.WithDeadline(ctx, deadline)
defer cancel()
// Len 1 timer

Možnosť 3: Zníž Retry Amplifikáciu

// PRED: Retries vytvárajú viac timeoutov
func callWithRetry(ctx context.Context) error {
    for i := 0; i < 3; i++ {
        ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
        err := call(ctx)
        cancel()
        if err == nil {
            return nil
        }
    }
    return err
}
// 3 timery per request

// PO: Jeden timeout naprieč retries
func callWithRetry(ctx context.Context) error {
    ctx, cancel := context.WithTimeout(ctx, 15*time.Second) // celkový budget
    defer cancel()

    for i := 0; i < 3; i++ {
        err := call(ctx) // znovupoužíva rovnaký timer
        if err == nil {
            return nil
        }
        if ctx.Err() != nil {
            return ctx.Err()
        }
    }
    return err
}
// 1 timer per request

Checklist

## Go Timer Heap Pressure

### Symptómy
- [ ] Periodické p99 latency špičky
- [ ] Špičky korelujú s GC pauzami
- [ ] Vysoký goroutine count
- [ ] Sieť vyzerá v poriadku počas špičiek

### Diagnostika
- [ ] Spočítaj context.WithTimeout volania per request
- [ ] Skontroluj execution trace pre timer vzory
- [ ] Profiluj pre time.*/runtime.* timer funkcie
- [ ] Monitoruj GC pause durations

### Riešenia
- [ ] Použi jednu propagovanú deadline
- [ ] Zníž vnorené timeout vrstvy
- [ ] Eliminuj retry amplifikáciu
- [ ] Zváž timer pooling pre custom use cases

Záver

Kontra-intuitívna lekcia: odstránenie vnútorných timeoutov a použitie jednej propagovanej deadline je bezpečnejšie než pridávanie timeoutov “pre istotu.” Viac timeoutov = viac timerov = viac GC tlaku = horšia latencia.

Súvisiace články

• Go Memory Profiling - Pochopenie Go pamäte
• Go cgo DNS Thread Explosion - Ďalšia Go runtime pasca