Day 114 — Performance Profiling the Full Stack

Key Concepts

Expected overhead for a well-implemented stack:

The WAF dominates because regex matching + multi-layer normalization is CPU-intensive. Optimization targets: pre-compile all regex (done), use sync.Pool for normalization buffers, short-circuit on first definitive block.

Exercise — Per-Middleware Latency Profiler

package profiling

import (
    "fmt"
    "net/http"
    "runtime/pprof"
    "sort"
    "sync"
    "sync/atomic"
    "time"
)

// MiddlewareTimer wraps a handler and records precise latency per layer
type MiddlewareTimer struct {
    name    string
    mu      sync.Mutex
    samples []int64 // nanoseconds
}

func NewMiddlewareTimer(name string) *MiddlewareTimer {
    return &MiddlewareTimer{name: name, samples: make([]int64, 0, 10000)}
}

func (mt *MiddlewareTimer) Wrap(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        next.ServeHTTP(w, r)
        elapsed := time.Since(start).Nanoseconds()
        mt.mu.Lock()
        mt.samples = append(mt.samples, elapsed)
        mt.mu.Unlock()
    })
}

// Percentile computes the Nth percentile of recorded samples
func (mt *MiddlewareTimer) Percentile(n float64) time.Duration {
    mt.mu.Lock()
    s := make([]int64, len(mt.samples))
    copy(s, mt.samples)
    mt.mu.Unlock()

    if len(s) == 0 {
        return 0
    }
    sort.Slice(s, func(i, j int) bool { return s[i] < s[j] })
    idx := int(float64(len(s)-1) * n / 100)
    return time.Duration(s[idx])
}

func (mt *MiddlewareTimer) Report() string {
    return fmt.Sprintf("%-30s p50=%6s p95=%6s p99=%6s (n=%d)",
        mt.name,
        mt.Percentile(50),
        mt.Percentile(95),
        mt.Percentile(99),
        len(mt.samples),
    )
}

// LoadGenerator creates concurrency goroutines each sending requests
type LoadGenerator struct {
    baseURL     string
    concurrency int
    total       int
    client      *http.Client
    requests    atomic.Int64
    errors      atomic.Int64
}

func NewLoadGenerator(baseURL string, concurrency, total int) *LoadGenerator {
    return &LoadGenerator{
        baseURL:     baseURL,
        concurrency: concurrency,
        total:       total,
        client:      &http.Client{Timeout: 10 * time.Second},
    }
}

func (lg *LoadGenerator) Run() (rps float64, errRate float64) {
    sem := make(chan struct{}, lg.concurrency)
    var wg sync.WaitGroup
    start := time.Now()

    for i := 0; i < lg.total; i++ {
        wg.Add(1)
        sem <- struct{}{}
        go func(i int) {
            defer wg.Done()
            defer func() { <-sem }()

            // Mix of request types: 80% valid, 10% WAF triggers, 5% rate limit, 5% auth fail
            var url string
            switch i % 20 {
            case 0, 1: // WAF trigger (10%)
                url = lg.baseURL + "/api/data?q=%27+OR+1%3D1--"
            case 2: // Rate limit (5%)
                for j := 0; j < 20; j++ { // burst
                    lg.client.Get(lg.baseURL + "/api/data")
                }
                return
            default: // Valid (85%)
                url = lg.baseURL + "/api/data"
            }

            resp, err := lg.client.Get(url)
            if err != nil {
                lg.errors.Add(1)
                return
            }
            resp.Body.Close()
            lg.requests.Add(1)
        }(i)
    }
    wg.Wait()
    elapsed := time.Since(start)

    total := float64(lg.requests.Load())
    errs := float64(lg.errors.Load())
    return total / elapsed.Seconds(), errs / (total + errs)
}

// CaptureProfile captures a CPU profile during load test
func CaptureProfile(duration time.Duration, outputPath string, fn func()) error {
    f, err := os.Create(outputPath)
    if err != nil {
        return err
    }
    defer f.Close()

    if err := pprof.StartCPUProfile(f); err != nil {
        return err
    }
    defer pprof.StopCPUProfile()

    done := make(chan struct{})
    go func() {
        fn()
        close(done)
    }()

    select {
    case <-done:
    case <-time.After(duration):
    }
    return nil
}

// Optimization targets based on profiling results:
//
// 1. WAF normalization — reduce allocations with sync.Pool
//    Before: 12 allocs/op, 3.2KB/op
//    After:  3 allocs/op, 512B/op  (reuse normalization buffer)
//
// 2. Regex matching — use sync.Once + package-level vars (already done in Week 10)
//    Before: regexp.MustCompile() on each request
//    After:  pre-compiled at init time
//
// 3. IP lookup — replace sync.Map with sharded map (reduce contention)
//    Before: sync.Map single lock
//    After:  16-shard map, shard by IP[last byte] & 0x0f