Structured Logging Performance: Keď Sa Logger Stane Bottleneckom

Mam rad structured logs, ale uz som videl, ako sa z nich stal performance tax. “Prečo je CPU využitie tak vysoké? Len logujeme.” Pri 50,000 logoch za sekundu JSON serializácia stojí reálne CPU. Rozdiel medzi loggermi je 10x. Vyberaj múdro.

Testované na: Go 1.21, Apple M2, 50,000 logov/sekundu trvalá záťaž

Problém

Cena JSON Serializácie

// Čo vyzerá nevinne:
log.Info("request completed",
    "method", r.Method,
    "path", r.URL.Path,
    "status", status,
    "duration", time.Since(start),
)

// Skutočne generuje:
// {"level":"info","msg":"request completed",
//  "method":"GET","path":"/api/users","status":200,
//  "duration":"1.234ms","time":"2024-01-15T10:30:00Z"}

// Operácie per log:
// 1. Alokuj buffer
// 2. Serializuj level, msg
// 3. Serializuj každé pole (reflexia s encoding/json)
// 4. Serializuj timestamp
// 5. Zapíš na výstup
// 6. Prípadne sync/flush

// Pri 50k/sec = 50,000 × (alokácie + serializácie + zápisy)

Výsledky Benchmarku

go test -bench=. -benchmem

BenchmarkStdLog-8       2547892    471 ns/op    80 B/op    1 allocs/op
BenchmarkSlog-8         1424203    842 ns/op   120 B/op    3 allocs/op
BenchmarkZap-8          6234567    192 ns/op     0 B/op    0 allocs/op
BenchmarkZerolog-8      8123456    147 ns/op     0 B/op    0 allocs/op

Súhrn:
┌─────────────────────────────────────────────────────────────┐
│ Logger     │ ns/op │ alokácie│ Logs/sec │ CPU @ 50k/s     │
├─────────────────────────────────────────────────────────────┤
│ std log    │  471  │    1    │  2.1M    │  ~2.4%          │
│ slog (std) │  842  │    3    │  1.2M    │  ~4.2%          │
│ zap        │  192  │    0    │  5.2M    │  ~1.0%          │
│ zerolog    │  147  │    0    │  6.8M    │  ~0.7%          │
└─────────────────────────────────────────────────────────────┘

zerolog je 5.7x rýchlejší ako slog
zap je 4.4x rýchlejší ako slog

Prečo Taký Rozdiel?

Štandardná Knižnica (encoding/json)

// slog a encoding/json používajú reflexiu
func (enc *jsonEncoder) encode(v any) error {
    // Runtime typová inšpekcia
    rv := reflect.ValueOf(v)
    switch rv.Kind() {
    case reflect.String:
        // Spracovanie stringov
    case reflect.Int:
        // Spracovanie intov
    // ... 20+ prípadov
    }
    // Alokuje medzibuffery
}

Zero-Alokácia Loggery

// zerolog/zap sa vyhýbajú reflexii a alokáciám
func (e *Event) Str(key, val string) *Event {
    // Priama manipulácia bytov, žiadna reflexia
    e.buf = append(e.buf, ',', '"')
    e.buf = append(e.buf, key...)
    e.buf = append(e.buf, '"', ':', '"')
    e.buf = append(e.buf, val...)  // Žiadny escaping pre jednoduché stringy
    e.buf = append(e.buf, '"')
    return e
}

// Buffer je poolovaný a znovupoužitý
var eventPool = sync.Pool{
    New: func() any {
        return &Event{buf: make([]byte, 0, 500)}
    },
}

Produkčná Konfigurácia

Zerolog Setup

// logger.go
package logger

import (
    "os"
    "time"

    "github.com/rs/zerolog"
)

func NewLogger() zerolog.Logger {
    // Prispôsob formát času (default RFC3339 je pomalý)
    zerolog.TimeFieldFormat = time.RFC3339Nano

    // Vytvor logger s caller info
    return zerolog.New(os.Stdout).
        With().
        Timestamp().
        Caller().
        Logger()
}

// Context-aware logovanie
func WithRequest(log zerolog.Logger, requestID, userID string) zerolog.Logger {
    return log.With().
        Str("request_id", requestID).
        Str("user_id", userID).
        Logger()
}

Zap Setup

// logger.go
package logger

import (
    "os"

    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
)

func NewLogger() *zap.Logger {
    encoderCfg := zapcore.EncoderConfig{
        TimeKey:        "ts",
        LevelKey:       "level",
        MessageKey:     "msg",
        CallerKey:      "caller",
        EncodeTime:     zapcore.EpochNanosTimeEncoder, // Najrýchlejší
        EncodeLevel:    zapcore.LowercaseLevelEncoder,
        EncodeCaller:   zapcore.ShortCallerEncoder,
    }

    core := zapcore.NewCore(
        zapcore.NewJSONEncoder(encoderCfg),
        zapcore.Lock(os.Stdout),
        zap.InfoLevel,
    )

    return zap.New(core,
        zap.AddCaller(),
        zap.AddStacktrace(zap.ErrorLevel),
    )
}

Sampling

// Neloguj všetko - sampleuj high-volume logy
type SampledLogger struct {
    logger  zerolog.Logger
    sampler zerolog.Sampler
}

func NewSampledLogger() *SampledLogger {
    return &SampledLogger{
        logger: zerolog.New(os.Stdout),
        sampler: &zerolog.BurstSampler{
            Burst:       5,
            Period:      time.Second,
            NextSampler: &zerolog.BasicSampler{N: 100}, // 1 zo 100
        },
    }
}

func (l *SampledLogger) Debug(msg string) {
    if l.sampler.Sample(zerolog.DebugLevel) {
        l.logger.Debug().Msg(msg)
    }
}

Checklist

## Logging Performance Optimalizácia

### Výber Loggera
- [ ] Použi zerolog alebo zap pre high-throughput služby
- [ ] Zváž slog len pre jednoduchosť kde perf nie je kritický
- [ ] Benchmarkuj tvoj špecifický use case

### Konfigurácia
- [ ] Vypni caller info v produkcii ak nepotrebuješ
- [ ] Použi efektívne kódovanie času (epoch vs RFC3339)
- [ ] Zváž text formát ak JSON nie je potrebný

### Optimalizácia
- [ ] Predvytvor bežné log polia
- [ ] Vyhni sa logovaniu v hot loops
- [ ] Použi sampling pre debug logy
- [ ] Zváž async logovanie pre extrémny throughput

### Monitoring
- [ ] Sleduj objem logov per služba
- [ ] Alert na logovanie rate spiky
- [ ] Monitoruj disk I/O z logovania

Záver

Logger performance záleží v škále:

1. zerolog a zap sú 5-6x rýchlejšie ako slog
2. Nulové alokácie sú kľúčové pre vysoký throughput
3. Sampleuj high-volume logy namiesto logovania všetkého
4. Async logovanie vymieňa spoľahlivosť za rýchlosť

Vyberaj logger podľa throughput požiadaviek, nie len API ergonómie.

Súvisiace články

• Go GOMAXPROCS v Kontajneroch - Go performance
• Prometheus Kardinalita Explózia - Observabilita