time.AfterFunc — Professional Level¶

Table of Contents¶

1. Introduction
2. The Production Mindset
3. Deadlines and Timeouts
4. Watchdogs
5. Idle Connection Sweepers
6. Rate Limiters and Token Buckets
7. Circuit Breakers
8. Retry with Backoff
9. Scheduled Jobs
10. Observability: Metrics for Timers
11. Observability: Logging
12. Observability: Tracing
13. Alerting
14. Capacity Planning
15. Postmortem 1: The Million Pending Callbacks
16. Postmortem 2: The Late Refund
17. Postmortem 3: The Watchdog That Stopped Watching
18. Postmortem 4: The Memory Leak from Captured Requests
19. Postmortem 5: Thundering Herd of Timer Fires
20. Operational Runbooks
21. Migration Stories
22. Hardened Reference Implementations
23. Cheat Sheet
24. Self-Assessment
25. Summary
26. Further Reading
27. Diagrams

Introduction¶

The senior file teaches what the runtime is doing. The professional file teaches what your team does with that knowledge in production: how you instrument the timers, what alerts you set up, how you respond when something breaks, and what you do in the postmortem to ensure it doesn't break again.

This file is organised around concrete production patterns and concrete incidents. Each pattern includes:

• The problem it solves.
• A complete, hardened implementation.
• The metrics you should export.
• The alerts you should set up.
• What to do when it breaks.

After this file you should be able to:

• Build, instrument, and operate timer-driven components in production.
• Diagnose a "callback didn't fire" or "callback fired too late" incident.
• Write a postmortem that produces actionable follow-up work.
• Coach your team on the same.

The Production Mindset¶

A few principles, before diving in.

Principle 1: assume something will go wrong¶

Production timers will:

• Fire late under load.
• Sometimes never fire (process restart, panic in callback).
• Capture more than you intended (memory bloat).
• Accumulate (leak) if not cleaned up.

Design for all of these.

Principle 2: instrument before you suspect a problem¶

By the time you suspect a timer issue, you want the data already. Add a "live timer count" metric the day you create the timer.

Principle 3: prefer simple to clever¶

A simple per-entry timer is easier to reason about than a custom timing wheel. Reach for cleverness only when profile data tells you to.

Principle 4: bound everything¶

• Cap the duration (no "1 year deadline" timers).
• Cap the count (no unbounded growth of timers).
• Cap the rate (throttle timer creation per second).

Principle 5: panic recovery is non-negotiable¶

Every callback in a production binary should defer recover(). A single unrecovered panic crashes the process.

Principle 6: test with mocked time¶

Real-time tests are flaky on CI. Inject a clock interface.

Principle 7: postmortem actionable¶

Every incident generates a postmortem; every postmortem generates at least one actionable follow-up. "Be more careful next time" is not actionable.

Deadlines and Timeouts¶

What¶

The most common production use of timers: bound the time something can take.

Example: HTTP request deadline¶

type Server struct {
    timeout time.Duration
}

func (s *Server) handle(w http.ResponseWriter, r *http.Request) {
    ctx, cancel := context.WithTimeout(r.Context(), s.timeout)
    defer cancel()

    result := make(chan response, 1)
    go func() {
        defer func() {
            if rec := recover(); rec != nil {
                result <- response{err: fmt.Errorf("panic: %v", rec)}
            }
        }()
        result <- doWork(ctx, r)
    }()

    select {
    case resp := <-result:
        s.metrics.WorkDuration.Observe(time.Since(time.Now()).Seconds())
        s.writeResp(w, resp)
    case <-ctx.Done():
        s.metrics.Timeouts.Inc()
        s.writeTimeout(w)
    }
}

Key points:

• The timeout is a context.WithTimeout. Under the hood it uses time.AfterFunc.
• The work goroutine recovers panics.
• A buffered channel (size 1) avoids leaking the goroutine.
• Both branches of the select have metric counters.

Example: downstream RPC deadline¶

func (c *Client) Call(ctx context.Context, req Request) (Response, error) {
    ctx, cancel := context.WithTimeout(ctx, c.timeout)
    defer cancel()

    return c.transport.Do(ctx, req)
}

The cleanest pattern. Push deadlines into contexts; let lower layers respect them.

Anti-pattern: hardcoded long deadline¶

// BAD
ctx, _ := context.WithTimeout(ctx, 24*time.Hour)

Either:

1. You don't really need a deadline (then don't add one).
2. You need a much shorter deadline.

24-hour deadlines accumulate timers in the runtime; if they "never" fire, the closures pin memory.

Pattern: deadline propagation¶

deadline, ok := ctx.Deadline()
if ok {
    if time.Until(deadline) < minimumWorkDuration {
        return ErrInsufficientTime
    }
}

Before doing expensive work, check the remaining deadline. Fail fast if there isn't enough time.

Pattern: shaving the deadline¶

When passing the context to a downstream service, give it slightly less time than you have, so you have buffer to handle the response.

downstreamCtx, cancel := context.WithTimeout(ctx, time.Until(deadline) - 100*time.Millisecond)
defer cancel()
resp, err := downstream.Call(downstreamCtx, req)

If the downstream returns close to its deadline, you still have 100 ms to format and send the response.

Metrics for deadlines¶

// Counter: timeouts per endpoint.
http_request_timeout_total{endpoint="/foo"}

// Histogram: time taken when not timed out.
http_request_duration_seconds{endpoint="/foo", outcome="ok"}

// Histogram: how close to deadline we got.
http_request_deadline_remaining_seconds{endpoint="/foo", outcome="ok"}

Alerts for deadlines¶

• "Timeout rate on /foo > 5% for 5 minutes."
• "p99 deadline remaining < 50 ms on /foo for 10 minutes" (suggests the deadline is too tight).
• "p99 deadline remaining = 0 for any endpoint" (timing out near the deadline often).

Watchdogs¶

What¶

A watchdog is a "dead man's switch" timer: it fires if the system fails to perform an expected action within a deadline. Used to detect:

• Hung worker threads.
• Stuck event loops.
• Lost connections.
• Missed heartbeats.

Implementation¶

type Watchdog struct {
    mu      sync.Mutex
    timer   *time.Timer
    timeout time.Duration
    onFire  func()
    fired   atomic.Bool
    closed  atomic.Bool
}

func NewWatchdog(timeout time.Duration, onFire func()) *Watchdog {
    w := &Watchdog{timeout: timeout, onFire: onFire}
    w.timer = time.AfterFunc(timeout, w.fire)
    return w
}

func (w *Watchdog) Touch() bool {
    w.mu.Lock()
    defer w.mu.Unlock()
    if w.closed.Load() || w.fired.Load() {
        return false
    }
    return w.timer.Reset(w.timeout)
}

func (w *Watchdog) Stop() {
    w.mu.Lock()
    defer w.mu.Unlock()
    w.closed.Store(true)
    w.timer.Stop()
}

func (w *Watchdog) fire() {
    if !w.fired.CompareAndSwap(false, true) {
        return
    }
    defer func() {
        if r := recover(); r != nil {
            log.Printf("watchdog panic: %v", r)
        }
    }()
    w.onFire()
}

Production deployment¶

A typical service has multiple watchdogs:

• "GC pauses longer than 1 second."
• "No request handled for 30 seconds."
• "Health check responder hasn't run in 10 seconds."

Each one has a Touch call somewhere in the path it monitors. If the path goes silent, the watchdog fires.

What the callback does¶

Usually one of:

• Log a structured error event with enough context for a human to investigate.
• Increment a counter.
• Trigger a healthcheck failure (causing the orchestrator to restart the pod).
• In extreme cases, os.Exit(1) to force a fresh process.

Don't restart yourself reflexively¶

A watchdog firing means something is wrong. Restarting may hide the underlying issue. Prefer logging and alerting first; restart only if the system is definitely stuck.

Metrics¶

watchdog_active{name="request_handling"}
watchdog_fires_total{name="request_handling"}
watchdog_touch_total{name="request_handling"}

Alerts¶

• "watchdog_fires_total > 0 over 5 minutes" — immediate page.
• "watchdog_touch_total flat for 60 seconds" — the path being watched is silent.

Idle Connection Sweepers¶

What¶

In a service that maintains long-lived connections (TCP, HTTP/2, WebSocket, database), idle connections cost memory and file descriptors. Sweep them.

Per-connection timer¶

type Conn struct {
    mu      sync.Mutex
    timer   *time.Timer
    timeout time.Duration
    closed  bool
    raw     io.ReadWriteCloser
}

func New(raw io.ReadWriteCloser, idle time.Duration) *Conn {
    c := &Conn{raw: raw, timeout: idle}
    c.timer = time.AfterFunc(idle, c.idleClose)
    return c
}

func (c *Conn) Touch() {
    c.mu.Lock()
    defer c.mu.Unlock()
    if c.closed {
        return
    }
    c.timer.Reset(c.timeout)
}

func (c *Conn) Close() error {
    c.mu.Lock()
    defer c.mu.Unlock()
    if c.closed {
        return nil
    }
    c.closed = true
    c.timer.Stop()
    return c.raw.Close()
}

func (c *Conn) idleClose() {
    c.mu.Lock()
    if c.closed {
        c.mu.Unlock()
        return
    }
    c.closed = true
    c.mu.Unlock()
    _ = c.raw.Close()
}

This is the same as the middle-level idle conn, with explicit handling for the Touch after close case.

Scaling considerations¶

A server with 100K open connections is 100K timers. Fine.

A server with 10M open connections is 10M timers. Not fine — switch to a sweeper.

Sweeper pattern¶

type Pool struct {
    mu     sync.Mutex
    conns  map[*Conn]struct{}
    ticker *time.Ticker
}

func (p *Pool) Run(timeout time.Duration) {
    p.ticker = time.NewTicker(timeout / 10)
    go func() {
        for range p.ticker.C {
            p.sweep(timeout)
        }
    }()
}

func (p *Pool) sweep(timeout time.Duration) {
    now := time.Now()
    var toClose []*Conn
    p.mu.Lock()
    for c := range p.conns {
        if now.Sub(c.lastTouched()) > timeout {
            toClose = append(toClose, c)
            delete(p.conns, c)
        }
    }
    p.mu.Unlock()
    for _, c := range toClose {
        c.Close()
    }
}

One ticker, O(N) per tick. The ticker fires at one-tenth the timeout granularity, so worst-case staleness is ~10% of the timeout.

Trade-offs¶

• Per-conn timers: O(1) close, exact timing, O(N) memory.
• Sweeper: O(N) per tick, looser timing, O(N) memory (smaller per entry — no timer overhead).

For < 100K conns, per-conn timers are simpler. For > 1M, sweeper. In between, profile.

Metrics¶

conn_idle_close_total
conn_idle_sweep_duration_seconds (histogram)
conn_active{purpose="grpc"}

Rate Limiters and Token Buckets¶

What¶

A rate limiter throttles operations to a maximum rate. Many implementations use timers.

Token bucket with refill timer¶

type Bucket struct {
    mu         sync.Mutex
    tokens     int
    capacity   int
    refillRate time.Duration
}

func NewBucket(capacity int, refillRate time.Duration) *Bucket {
    b := &Bucket{capacity: capacity, tokens: capacity, refillRate: refillRate}
    b.scheduleRefill()
    return b
}

func (b *Bucket) scheduleRefill() {
    time.AfterFunc(b.refillRate, func() {
        b.mu.Lock()
        if b.tokens < b.capacity {
            b.tokens++
        }
        b.mu.Unlock()
        b.scheduleRefill()
    })
}

func (b *Bucket) Allow() bool {
    b.mu.Lock()
    defer b.mu.Unlock()
    if b.tokens > 0 {
        b.tokens--
        return true
    }
    return false
}

This works but has a long-running self-rescheduling timer. If the bucket is never used, the timer keeps firing.

Lazy refill pattern¶

type LazyBucket struct {
    mu         sync.Mutex
    tokens     float64
    capacity   float64
    refillRate float64 // tokens per second
    last       time.Time
}

func (b *LazyBucket) Allow() bool {
    b.mu.Lock()
    defer b.mu.Unlock()
    now := time.Now()
    elapsed := now.Sub(b.last).Seconds()
    b.tokens = math.Min(b.capacity, b.tokens + elapsed*b.refillRate)
    b.last = now
    if b.tokens >= 1 {
        b.tokens--
        return true
    }
    return false
}

No timer at all. Tokens are computed on demand. Cleaner for most use cases.

When to use a timer¶

Use a timer when:

• You need to enforce a refill rate (e.g., for a hardware-bound resource).
• You need an event at refill (e.g., wake up waiting goroutines).

Otherwise, prefer lazy refill.

Triggered rate limits¶

A timer can fire when a rate is exceeded:

type Limit struct {
    mu    sync.Mutex
    count int
    timer *time.Timer
}

func (l *Limit) IncrementAndMaybeBlock(threshold int, cooldown time.Duration) bool {
    l.mu.Lock()
    defer l.mu.Unlock()
    l.count++
    if l.count >= threshold {
        if l.timer == nil {
            l.timer = time.AfterFunc(cooldown, func() {
                l.mu.Lock()
                l.count = 0
                l.timer = nil
                l.mu.Unlock()
            })
        }
        return false
    }
    return true
}

Counts up; after threshold events, blocks further events for cooldown.

Distributed rate limits¶

In a distributed system, in-process timers are insufficient — different processes have different views. Use Redis with TTLs, or a dedicated rate-limit service.

Circuit Breakers¶

What¶

A circuit breaker prevents repeated failures from a downstream service from cascading. After enough failures, the breaker "opens" and rejects requests for a cooldown period. After cooldown, it tries "half-open" — a few requests pass through to see if the downstream has recovered.

Implementation¶

type Breaker struct {
    mu          sync.Mutex
    state       State // closed, open, half-open
    failures    int
    threshold   int
    resetTimer  *time.Timer
    cooldown    time.Duration
}

type State int

const (
    Closed State = iota
    Open
    HalfOpen
)

func (b *Breaker) Call(op func() error) error {
    b.mu.Lock()
    state := b.state
    b.mu.Unlock()

    switch state {
    case Open:
        return ErrOpen
    case Closed, HalfOpen:
        err := op()
        b.recordResult(err)
        return err
    }
    return nil
}

func (b *Breaker) recordResult(err error) {
    b.mu.Lock()
    defer b.mu.Unlock()
    if err == nil {
        if b.state == HalfOpen {
            b.state = Closed
        }
        b.failures = 0
        return
    }
    b.failures++
    if b.failures >= b.threshold {
        b.state = Open
        b.resetTimer = time.AfterFunc(b.cooldown, func() {
            b.mu.Lock()
            defer b.mu.Unlock()
            b.state = HalfOpen
            b.failures = 0
        })
    }
}

The AfterFunc schedules the open -> half-open transition.

Production polish¶

• Add jitter to the cooldown to avoid synchronised half-open probes from many breakers.
• Count successes in half-open before declaring closed.
• Emit metrics on every state change.

Metrics¶

breaker_state{name="payments", state="open"}  # gauge
breaker_state_change_total{name="payments", from="closed", to="open"}
breaker_open_duration_seconds (histogram)

Alerts¶

• "Breaker open for > 5 minutes" — downstream is sustained-broken.
• "Breaker oscillating open/closed > 5 times in 10 minutes" — flapping; consider tuning thresholds.

Retry with Backoff¶

What¶

Retry transient failures with exponentially increasing delays.

Implementation¶

type Retrier struct {
    mu      sync.Mutex
    timer   *time.Timer
    attempt int
    base    time.Duration
    max     time.Duration
    cap     int
    op      func(ctx context.Context) error
    onDone  func(error)
    ctx     context.Context
    cancel  context.CancelFunc
}

func NewRetrier(ctx context.Context, op func(context.Context) error, onDone func(error)) *Retrier {
    rctx, cancel := context.WithCancel(ctx)
    return &Retrier{
        base:   100 * time.Millisecond,
        max:    10 * time.Second,
        cap:    5,
        op:     op,
        onDone: onDone,
        ctx:    rctx,
        cancel: cancel,
    }
}

func (r *Retrier) Start() {
    r.run()
}

func (r *Retrier) Cancel() {
    r.cancel()
    r.mu.Lock()
    if r.timer != nil {
        r.timer.Stop()
    }
    r.mu.Unlock()
}

func (r *Retrier) run() {
    if r.ctx.Err() != nil {
        r.onDone(r.ctx.Err())
        return
    }
    err := r.op(r.ctx)
    if err == nil {
        r.onDone(nil)
        return
    }
    r.mu.Lock()
    r.attempt++
    if r.attempt > r.cap {
        r.mu.Unlock()
        r.onDone(fmt.Errorf("retries exhausted: %w", err))
        return
    }
    delay := r.base * time.Duration(1<<(r.attempt-1))
    if delay > r.max {
        delay = r.max
    }
    delay = jitter(delay)
    r.timer = time.AfterFunc(delay, r.run)
    r.mu.Unlock()
}

func jitter(d time.Duration) time.Duration {
    return d/2 + time.Duration(rand.Int63n(int64(d/2)))
}

Notes:

• jitter randomises the delay by 50% — important for avoiding thundering-herd retries from many clients.
• r.op(r.ctx) respects context cancellation, so a cancelled retry doesn't keep trying.
• The Cancel method stops both the timer and the context.

Metrics¶

retries_total{name="payment_charge", outcome="success"}
retries_total{name="payment_charge", outcome="exhausted"}
retry_attempts_histogram{name="payment_charge"}

Anti-pattern: no cap¶

func retry(op func() error) {
    if err := op(); err != nil {
        time.AfterFunc(time.Second, func() { retry(op) })
    }
}

Infinite retry. If op always fails (e.g., the resource is permanently gone), this consumes resources forever. Always cap.

Scheduled Jobs¶

What¶

Jobs that run at a future time, possibly cancelled before then.

Simple scheduler¶

type Scheduler struct {
    mu   sync.Mutex
    jobs map[string]*time.Timer
}

func New() *Scheduler {
    return &Scheduler{jobs: map[string]*time.Timer{}}
}

func (s *Scheduler) Schedule(id string, at time.Time, fn func()) {
    s.mu.Lock()
    defer s.mu.Unlock()
    if t, ok := s.jobs[id]; ok {
        t.Stop()
    }
    delay := time.Until(at)
    if delay < 0 {
        delay = 0
    }
    s.jobs[id] = time.AfterFunc(delay, func() {
        defer func() {
            if r := recover(); r != nil {
                log.Printf("scheduled job %s panicked: %v", id, r)
            }
        }()
        s.mu.Lock()
        delete(s.jobs, id)
        s.mu.Unlock()
        fn()
    })
}

func (s *Scheduler) Cancel(id string) bool {
    s.mu.Lock()
    defer s.mu.Unlock()
    t, ok := s.jobs[id]
    if !ok {
        return false
    }
    delete(s.jobs, id)
    return t.Stop()
}

Supports cancel and re-schedule by ID. Cleans up the map entry on fire.

Persistence¶

For jobs that should survive process restart, persist to a database (Postgres, Redis). On startup, reload pending jobs and re-schedule.

type DurableScheduler struct {
    db Database
    *Scheduler
}

func (s *DurableScheduler) Schedule(id string, at time.Time, fn func()) {
    s.db.SaveJob(id, at)
    s.Scheduler.Schedule(id, at, func() {
        s.db.DeleteJob(id)
        fn()
    })
}

func (s *DurableScheduler) Restore() {
    jobs := s.db.LoadPendingJobs()
    for _, j := range jobs {
        s.Schedule(j.ID, j.At, j.Fn)
    }
}

The job's effect happens once: the timer fires, the function runs, the DB record is deleted. On crash mid-function, the DB still has the record; on restart, the job is re-scheduled and runs (potentially again — design the function to be idempotent).

Scale considerations¶

For 1K scheduled jobs, in-memory plus periodic DB persist is fine.

For 100K, group by deadline buckets, persist in batches.

For 1M+, consider a dedicated job scheduler service (Sidekiq-style with persistence; or Temporal, or a custom solution).

Cron-like schedules¶

For recurring schedules ("every Monday at 9 AM"), parse a cron expression, compute the next fire time, schedule with AfterFunc, and reschedule from the callback.

type Cron struct {
    expr    string
    nextFn  func() func() // returns the next fire time computer
    fn      func()
    timer   *time.Timer
}

func (c *Cron) Start() {
    next := c.nextFn()()
    c.timer = time.AfterFunc(time.Until(next), c.fire)
}

func (c *Cron) fire() {
    defer func() {
        if r := recover(); r != nil {
            log.Printf("cron panic: %v", r)
        }
    }()
    c.fn()
    next := c.nextFn()()
    c.timer = time.AfterFunc(time.Until(next), c.fire)
}

Production cron libraries handle DST, leap seconds, and timezone changes — write your own only as a learning exercise.

Observability: Metrics for Timers¶

What to measure¶

For each timer-based component, export:

• Count: how many timers are live right now.
• Rate: creations per second, stops per second, fires per second.
• Latency: time between scheduled fire and actual fire.

Implementation¶

Wrap time.AfterFunc:

type Metrics struct {
    Live    prometheus.Gauge
    Created prometheus.Counter
    Stopped prometheus.Counter
    Fired   prometheus.Counter
    Latency prometheus.Histogram
}

func Observed(d time.Duration, f func(), m *Metrics) *time.Timer {
    m.Live.Inc()
    m.Created.Inc()
    scheduledFor := time.Now().Add(d)
    var t *time.Timer
    t = time.AfterFunc(d, func() {
        late := time.Since(scheduledFor).Seconds()
        m.Latency.Observe(late)
        m.Fired.Inc()
        m.Live.Dec()
        defer func() {
            if r := recover(); r != nil {
                log.Printf("timer panic: %v", r)
            }
        }()
        f()
    })
    // We need to wrap Stop to update Live.
    return t // Caller must use this wrapper if they want correct Live counts.
}

The wrapper approach has limits — Stop calls on the bare *time.Timer won't decrement Live. For full bookkeeping, return a wrapper type:

type ObservedTimer struct {
    t       *time.Timer
    m       *Metrics
    stopped atomic.Bool
}

func (ot *ObservedTimer) Stop() bool {
    if !ot.stopped.CompareAndSwap(false, true) {
        return false
    }
    ok := ot.t.Stop()
    if ok {
        ot.m.Stopped.Inc()
        ot.m.Live.Dec()
    }
    return ok
}

Dashboards¶

Standard panel set:

• "Live timers over time" — should be stable in steady state.
• "Create rate vs Stop rate vs Fire rate" — should balance.
• "Timer latency histogram" — p50, p99, p999.

If "live timers" climbs without bound, you have a leak. Investigate creates vs stops.

Labels¶

Label by purpose:

timer_live{purpose="session_idle"}
timer_live{purpose="request_deadline"}
timer_live{purpose="cleanup"}

Different purposes have different baselines.

Cardinality¶

Don't label by user ID, request ID, or any high-cardinality field. The label set must be bounded.

Observability: Logging¶

What to log¶

When a timer fires unexpectedly (the typical case for watchdogs and deadlines), log:

• Timestamp.
• Purpose / name of the timer.
• Scheduled duration.
• Actual duration (if measurable).
• Context (request ID, user ID, etc.).

Format¶

Structured (JSON) logs are essential. Plain text is unsearchable in production.

log.WithFields(logrus.Fields{
    "purpose": "request_deadline",
    "duration_ms": 5000,
    "request_id": ctx.Value("request_id"),
    "url": r.URL.Path,
}).Warn("request deadline fired")

What not to log¶

• The full closure contents (PII).
• Stack traces of the caller (callback runs in its own goroutine — the caller's stack is gone).
• High-frequency timers' every fire (rate-limit your logging).

Log levels¶

• Debug: every fire (for development).
• Info: state transitions (breaker open/closed).
• Warn: unexpected fires (watchdog triggered, retry exhausted).
• Error: panics in callbacks.

Observability: Tracing¶

What¶

Distributed tracing connects a timer's effect to the request that scheduled it.

Example¶

func handle(ctx context.Context, w http.ResponseWriter, r *http.Request) {
    ctx, span := tracer.Start(ctx, "handle")
    defer span.End()

    deadline := time.Now().Add(5 * time.Second)
    span.SetAttributes(attribute.String("deadline", deadline.String()))

    ctx, cancel := context.WithDeadline(ctx, deadline)
    defer cancel()

    cleanup := context.AfterFunc(ctx, func() {
        _, cspan := tracer.Start(ctx, "cleanup")
        defer cspan.End()
        // ... cleanup work ...
    })
    defer cleanup()

    // ... main work ...
}

The cleanup span is linked to the request span by the shared ctx. In your tracing UI, you can see the cleanup nested inside the request.

Limitations¶

• Each timer fire creates a new goroutine. The trace context propagates only if the callback captures and uses it.
• High-frequency timers should sample tracing to avoid overhead.

Alerting¶

Principles¶

• Alert on symptoms users observe (slow responses, failed requests), not on internal states.
• Page only for actionable issues.
• Have a runbook for every page-level alert.

Timer-specific alerts¶

• Timer leak: live_timers doubled over baseline. Severity: investigate.
• Watchdog fire: watchdog_fires_total > 0. Severity: page.
• Late fires: p99 timer latency > expected. Severity: investigate.
• Sudden burst: timer fires > 10× baseline in 5 minutes. Severity: investigate.

Alert hygiene¶

Review alerts quarterly:

• "Does this alert still fire?"
• "Did anyone respond when it fired?"
• "Was the response useful?"

Retire alerts that no longer matter.

Capacity Planning¶

Memory budget¶

Plan for:

• Each timer: ~150 bytes (timer struct + heap entry).
• Each closure: variable; audit for size.

A service with 100K typical live timers using 200-byte closures: ~35 MB.

At 1M live timers with the same closures: 350 MB. Noticeable.

CPU budget¶

Heap operations are O(log N). At N = 1M, log N = 20. Each op ~100 ns. So 1M creates + 1M stops + 1M fires per second = 6M ops/sec × 100ns × 20 = 12 sec/sec — i.e., 1200% of one core. Infeasible.

In practice you won't have 1M ops/sec. But at 100K ops/sec, you might use 1.2% of a core for heap operations. At 1M ops/sec, you should not be using time.AfterFunc.

Goroutine budget¶

Fire rate = goroutine spawn rate. Each spawn is ~300 ns. At 100K fires/sec: 30 ms/sec of CPU = 3% of a core. At 1M fires/sec: 30% of a core.

The bigger issue is the spike pattern. If 100K timers fire in 100 ms, the goroutine count spikes by 100K, stressing the runtime briefly.

Mitigation¶

• Reduce timer count via batching.
• Add jitter to deadlines to spread fires.
• Use a worker pool to limit concurrent execution.

Postmortem 1: The Million Pending Callbacks¶

Title¶

"AfterFunc Memory Leak in Order Service"

Incident summary¶

• Date: redacted
• Severity: P2 (degraded service; no customer-facing outage yet)
• Duration: 4 hours from detection to mitigation
• Impact: Order service container restarted every 30 minutes due to OOM kills; affected 3% of orders (those that hit a restart)

Timeline¶

• T0: Deployed v1.5.0 with a new "delayed cleanup" feature.
• T+2h: PagerDuty fires "Order service OOM kill" alert.
• T+5h: On-call engineer ack'd, started investigation.
• T+6h: Identified that goroutine count was 5M at OOM time (normal: 1K).
• T+7h: Heap profile showed 5M time.Timer allocations.
• T+8h: Traced to a new time.AfterFunc(time.Hour, ...) in the request path. Each request created one; none were stopped.
• T+9h: Rolled back to v1.4.9. OOMs stopped.

Root cause¶

The new "delayed cleanup" feature was meant to clean up resources 1 hour after a request finished. The implementation:

func handle(r *Request) {
    // ... handle the request ...
    time.AfterFunc(time.Hour, func() {
        cleanupResource(r.ResourceID)
    })
}

Two problems:

1. The closure captured r, the entire request object (large; included the response body, ~50 KB on average).
2. The timer was never stopped, even after the resource was cleaned up by other means.

At 1000 req/s with 1-hour timers, ~3.6M timers were live at steady state. Plus the captures: ~180 GB of pinned memory.

Why the existing tests missed it¶

• Integration tests used 1-minute timeouts; the 1-hour timer never fired in tests.
• Load tests didn't run for an hour.
• Memory limits in dev/staging were higher than in prod.

Mitigation¶

1. Stop the timer if cleanup happens via other means.
2. Capture only r.ResourceID, not r.
3. Lower the duration to 5 minutes — the intent was "if no other cleanup happens, clean up eventually."

The patched code:

func handle(r *Request) {
    resourceID := r.ResourceID
    timer := time.AfterFunc(5*time.Minute, func() {
        cleanupResource(resourceID)
    })
    r.OnCleanup = func() { timer.Stop() } // hook for normal cleanup
}

Lessons¶

1. Audit every time.AfterFunc for capture size and lifetime.
2. Add a metric: live timers per purpose. Would have alerted us at 100K.
3. Lower TTLs are better. "Eventually clean up" rarely needs an hour.
4. Test memory under sustained load — not just functionality.

Follow-up actions¶

1. Add timer_live{purpose="X"} metrics to all uses of AfterFunc.
2. Code review checklist: "What does the closure capture?"
3. Soak test: run 5% prod traffic for 24h on a canary, monitor memory.
4. Lint: warn on time.AfterFunc durations > 10 minutes.

Postmortem 2: The Late Refund¶

Title¶

"Payment Service Double-Refund Due to Late Timer"

Incident summary¶

• Date: redacted
• Severity: P1 (financial impact)
• Duration: 72 minutes total; 12 incidents over the window
• Impact: 12 customers received double refunds totalling $4,800

Timeline¶

• T0: Deploy v2.3.1 (new payment retry logic).
• T+2d: First complaint: customer received a refund and a successful order.
• T+2d 1h: Customer support reports 3 more cases.
• T+2d 3h: Engineering acknowledged.
• T+2d 4h: Traced to a 30-second "auto-refund if no confirmation" timer.
• T+2d 6h: Manually refunded inverse for affected customers ($-4,800 reversal applied).
• T+2d 8h: Patch deployed; behaviour confirmed fixed.

Root cause¶

The payment service charged a card, then started a 30-second timer to refund if the order wasn't confirmed:

func charge(order Order) error {
    if err := paymentGateway.Charge(order.Amount); err != nil {
        return err
    }
    time.AfterFunc(30*time.Second, func() {
        if !orderStore.IsConfirmed(order.ID) {
            paymentGateway.Refund(order.Amount, order.ID)
        }
    })
    return nil
}

Two issues:

1. GC pause caused 31-second delay. The timer fired late. By then, the order was confirmed. The IsConfirmed check returned true, but the previous check (visible to the callback's prior reading) had been false. Wait — actually, the check ran late; let me re-examine.

After investigation: the actual problem was different. The timer fired at the correct time, but orderStore.IsConfirmed had a 100 ms latency (cache + DB). The order was confirmed during this read, so the read returned a stale "not confirmed." The refund proceeded.

This is a TOCTOU bug: time-of-check (read) vs. time-of-use (refund).

1. The refund itself wasn't idempotent. A second refund could be issued without the gateway noticing.

Mitigation¶

1. Make the read atomic with the refund, via the gateway's idempotency keys.
2. Pass an idempotency_key = "refund-" + order.ID to the refund call. The gateway de-duplicates.

The patched code:

time.AfterFunc(30*time.Second, func() {
    paymentGateway.RefundIdempotent(order.Amount, order.ID, "refund-"+order.ID)
})

// inside RefundIdempotent: gateway checks if a refund with this key already happened;
// if so, returns success without doing anything.

The "is confirmed?" check became unnecessary — the gateway de-duplicates.

Lessons¶

1. Timers fire on their own goroutine; their checks of shared state can race with mutations.
2. Idempotency keys are the right tool for "do at most one of these" with potentially racing callers.
3. Don't gate critical actions on stale state.

Follow-up actions¶

1. Add idempotency keys to every payment operation.
2. Review every time.AfterFunc in the payment service for TOCTOU bugs.
3. Add a metric: timer fires that resulted in refunds (vs. confirmed orders).
4. Slack alert if "refund after confirmation" happens — should be zero in steady state.

Postmortem 3: The Watchdog That Stopped Watching¶

Title¶

"Health Check Watchdog Never Fired During 4-Hour Database Outage"

Incident summary¶

• Date: redacted
• Severity: P2 (no immediate customer impact, but watchdog was supposed to detect this)
• Duration: 4 hours of database outage; the watchdog should have fired within 30 seconds
• Impact: No additional customer impact, but we lost confidence in our self-healing.

Timeline¶

• T0: Database failover failed; primary DB unreachable.
• T+30s: Watchdog was supposed to fire and trigger a restart. It did not.
• T+4h: Manual intervention restored service.
• T+1d: Investigation: why didn't the watchdog fire?

Root cause¶

The watchdog was implemented as:

type Watchdog struct {
    timer *time.Timer
    timeout time.Duration
}

func (w *Watchdog) Touch() {
    w.timer.Reset(w.timeout)
}

The Touch was called from inside the request handler, after each successful request. When the DB went down, requests failed quickly, the handler returned an error, but Touch was still called at the end of the handler (after the error path).

Specifically, the error path was:

func handle(w http.ResponseWriter, r *http.Request) {
    defer w.watchdog.Touch() // BUG: touches regardless of success
    if err := process(r); err != nil {
        http.Error(w, err.Error(), 500)
        return
    }
    // ...
}

The watchdog touched on every request, including the failing ones. As long as requests were being received, the watchdog was happy — even though every single request was failing.

Mitigation¶

1. Touch the watchdog only on successful processing.
2. Add a separate watchdog for "successful requests in the last N seconds > 0."

The patched code:

func handle(w http.ResponseWriter, r *http.Request) {
    if err := process(r); err != nil {
        http.Error(w, err.Error(), 500)
        return
    }
    w.watchdog.Touch() // only touch on success
}

Lessons¶

1. A watchdog measures the wrong thing if you touch it from a wrong place.
2. The semantic should be "successful work performed," not "request handled."
3. Test the watchdog by deliberately breaking the path it watches.

Follow-up actions¶

1. Add a watchdog test: stub out the DB, verify watchdog fires within timeout.
2. Review all watchdogs for "what does Touch actually measure?"
3. Game-day exercise: simulate downstream outage; verify alerts fire.

Postmortem 4: The Memory Leak from Captured Requests¶

Title¶

"Image Service OOM Due to Captured Request Bodies"

Incident summary¶

• Date: redacted
• Severity: P2
• Duration: 1 week (slow growth; OOM during peak)
• Impact: Pod restarts during peak hours; some image upload failures.

Timeline¶

• T0: Deploy v3.1.0 (added image-conversion delay feature).
• T+1w: First OOM during peak.
• T+1w 1d: Investigation.

Root cause¶

The image service offered a "delayed conversion" feature: upload an image, conversion happens 5 minutes later. Implementation:

func upload(r *Request) {
    saveImage(r.ImageData) // 5 MB average

    time.AfterFunc(5*time.Minute, func() {
        convertImage(r.ImageData)
    })
}

The closure captured r.ImageData. Each upload pinned 5 MB of memory for 5 minutes. At 1000 uploads/min for 5 min: 5,000 × 5 MB = 25 GB.

The pod had a 4 GB memory limit.

Mitigation¶

1. Save the image to a path; capture the path, not the bytes.

func upload(r *Request) {
    path := saveImage(r.ImageData) // returns "/tmp/xxx.jpg"
    r.ImageData = nil               // help GC

    time.AfterFunc(5*time.Minute, func() {
        data := readFile(path)
        convertImage(data)
        deleteFile(path)
    })
}

The closure captures path (a small string), not r.ImageData. The byte slice can be GC'd after upload returns.

Lessons¶

1. Closure capture matters for memory.
2. For large objects, store on disk (or external storage); capture the reference.
3. Set memory limits in tests; verify behaviour under realistic load.

Follow-up actions¶

1. Audit every time.AfterFunc for capture sizes > 1 KB.
2. Add a lint rule: warn on *Request captured in AfterFunc closure.
3. Memory soak test in CI: run 1 hour with prod-like traffic; verify steady state.

Postmortem 5: Thundering Herd of Timer Fires¶

Title¶

"Goroutine Spike Causing GC Storm Every 5 Minutes"

Incident summary¶

• Date: redacted
• Severity: P2
• Duration: 3 hours visible; latency degraded throughout
• Impact: p99 latency went from 200 ms to 1.8 seconds.

Timeline¶

• T0: Deploy v4.0.1, a new "cache refresh" feature.
• T+5m: First p99 spike.
• T+10m: Pattern visible: every 5 minutes.
• T+30m: Investigation begins.

Root cause¶

The cache had 50K entries, each with a 5-minute TTL. The implementation:

func (c *Cache) Set(k, v string) {
    c.entries[k] = v
    time.AfterFunc(5*time.Minute, func() {
        delete(c.entries, k)
    })
}

At startup, 50K entries were loaded in a tight loop. 5 minutes later, all 50K timers fired within ~100 ms. The runtime spawned 50K goroutines simultaneously. The goroutine count went from 1K to 51K; GC pressure went up; subsequent GC cycles took 500-800 ms.

Mitigation¶

1. Switch to a single sweeper timer instead of one timer per entry.

func (c *Cache) Sweep() {
    c.mu.Lock()
    defer c.mu.Unlock()
    now := time.Now()
    for k, e := range c.entries {
        if now.After(e.expiry) {
            delete(c.entries, k)
        }
    }
}

func (c *Cache) Run() {
    ticker := time.NewTicker(30 * time.Second)
    go func() {
        for range ticker.C {
            c.Sweep()
        }
    }()
}

One goroutine, one ticker. Sweep is O(N) but runs only once every 30 seconds.

1. Add jitter to per-entry timers, if per-entry timers are kept.

ttl := 5*time.Minute + time.Duration(rand.Intn(60))*time.Second
time.AfterFunc(ttl, func() { delete(c.entries, k) })

Spreads fires across 60 seconds; no spike.

Lessons¶

1. N timers firing simultaneously creates a goroutine spike.
2. Per-entry timers don't scale.
3. Jitter is essentially free and avoids thundering herds.

Follow-up actions¶

1. Add a metric: goroutine count delta over 1-second windows.
2. Alert if delta > 5K (indicating a fire spike).
3. Refactor every cache to use a sweeper or jitter.
4. Document the per-entry-timer scalability limit in our internal docs.

Operational Runbooks¶

Runbook 1: "Timer Leak Suspected"¶

Symptoms:

• live_timers gauge climbing without bound.
• OOM kills with goroutine count > 100K.

Investigation:

1. Fetch goroutine profile: /debug/pprof/goroutine.
2. Identify which AfterFunc callsite is dominant.
3. Check git log for recent changes to that path.
4. Heap profile: /debug/pprof/heap. Look for runtimeTimer allocations.

Mitigation:

1. If a recent deploy caused it: roll back.
2. Otherwise: identify the missing Stop call, deploy a fix.

Postmortem:

• Quantify customer impact.
• Add the relevant metric and alert.
• Update lint rules if applicable.

Runbook 2: "Callback Didn't Fire"¶

Symptoms:

• A scheduled action did not happen.
• No log entry for the expected fire.

Investigation:

1. Was the timer created? Check application logs.
2. Was it stopped? Check application logs.
3. Did the process restart between schedule and fire? Check pod restart logs.
4. Did the callback panic? Check error logs.

Mitigation:

• If the process restarted, the timer is gone; nothing to do unless durable.
• If the callback panicked: identify and fix the panic. Add defer recover().
• If the timer was stopped erroneously: identify and fix the Stop call.

Runbook 3: "Late Fires"¶

Symptoms:

• Timer latency p99 > expected (e.g., > 100 ms when fires are supposed to be sub-millisecond).

Investigation:

1. CPU profile: is the runtime busy? Look for high runtime.systemstack or runtime.findRunnable.
2. Goroutine count: are there many runnable goroutines?
3. GC: are stop-the-world pauses unusually long?
4. Are there many timers? pprof heap profile.

Mitigation:

• Reduce timer count (batching).
• Increase GOMAXPROCS.
• Tune GC (e.g., GOGC=200 for less frequent GC).
• Add jitter to spread fires.

Runbook 4: "Watchdog Fired"¶

Symptoms:

• watchdog_fires_total{name="X"} increased.
• Pager going off.

Investigation:

1. What does the watchdog measure? Re-read the runbook for that watchdog.
2. Was the watched path actually broken? Check the upstream metrics.
3. Was the watchdog Touched recently? Trace back through logs.

Mitigation:

• If the watched path is broken: fix it. The watchdog did its job.
• If the watchdog is false-firing: fix the watchdog (it's measuring the wrong thing).
• Restart the pod if the system is wedged.

Migration Stories¶

Story 1: Replacing time.After with reused Timer in a hot loop¶

A service had:

for {
    select {
    case <-ctx.Done():
        return
    case <-time.After(time.Second):
        doWork()
    }
}

CPU profile showed 12% time in time.After allocations. Fixed by:

t := time.NewTimer(time.Second)
defer t.Stop()
for {
    select {
    case <-ctx.Done():
        return
    case <-t.C:
        doWork()
        t.Reset(time.Second)
    }
}

CPU dropped by 11.5%.

Story 2: Replacing goroutine+Sleep with AfterFunc¶

A service had millions of "schedule a thing in N seconds" calls per day, each as:

go func() {
    time.Sleep(d)
    doIt()
}()

Goroutine count averaged 50K (the sleeping ones). Replaced with time.AfterFunc(d, doIt). Goroutine count dropped to 5K (the actively-running ones at any moment).

Story 3: Replacing per-entry cache timers with a sweeper¶

A 200K-entry cache had per-entry AfterFunc timers. Memory: 800 MB just for timers. Switched to a 1-minute sweeper. Memory dropped to 80 MB.

Trade-off: entries now expire ±60 seconds late. Acceptable for the use case.

Story 4: Replacing goroutine+ctx.Done with context.AfterFunc¶

A request handler had:

go func() {
    <-ctx.Done()
    cleanup()
}()

At 5000 req/s, 5000 parked goroutines per second × ~5 seconds average context lifetime = 25K parked goroutines.

Replaced with:

stop := context.AfterFunc(ctx, cleanup)
defer stop()

Goroutine count dropped by ~25K.

Hardened Reference Implementations¶

Observable AfterFunc¶

// Package observed wraps time.AfterFunc with metrics, panic recovery, and tracing.
package observed

import (
    "context"
    "log"
    "runtime/debug"
    "sync/atomic"
    "time"
)

type Metrics interface {
    IncCreated(purpose string)
    IncFired(purpose string)
    IncStopped(purpose string)
    IncPanic(purpose string)
    ObserveLatency(purpose string, late time.Duration)
}

type Timer struct {
    inner    *time.Timer
    purpose  string
    metrics  Metrics
    schedFor time.Time
    stopped  atomic.Bool
}

func AfterFunc(purpose string, d time.Duration, f func(), m Metrics) *Timer {
    schedFor := time.Now().Add(d)
    t := &Timer{purpose: purpose, metrics: m, schedFor: schedFor}
    t.inner = time.AfterFunc(d, func() {
        late := time.Since(schedFor)
        m.ObserveLatency(purpose, late)
        m.IncFired(purpose)
        defer func() {
            if r := recover(); r != nil {
                m.IncPanic(purpose)
                log.Printf("timer panic [%s]: %v\n%s", purpose, r, debug.Stack())
            }
        }()
        f()
    })
    m.IncCreated(purpose)
    return t
}

func (t *Timer) Stop() bool {
    if !t.stopped.CompareAndSwap(false, true) {
        return false
    }
    ok := t.inner.Stop()
    if ok {
        t.metrics.IncStopped(t.purpose)
    }
    return ok
}

func (t *Timer) Reset(d time.Duration) {
    // Note: Reset's boolean is dropped here as it's rarely useful for AfterFunc.
    t.schedFor = time.Now().Add(d)
    t.inner.Reset(d)
}

// AfterFuncContext combines time.AfterFunc with context cancellation.
func AfterFuncContext(ctx context.Context, purpose string, d time.Duration, f func(), m Metrics) *Timer {
    t := AfterFunc(purpose, d, f, m)
    context.AfterFunc(ctx, func() {
        t.Stop()
    })
    return t
}

This is what you ship in production. Wrap time.AfterFunc with bookkeeping, panic recovery, and tracing.

Bounded scheduler¶

package scheduler

import (
    "container/heap"
    "context"
    "errors"
    "sync"
    "time"
)

// Scheduler runs jobs at their scheduled times. Bounded by maxJobs.
type Scheduler struct {
    mu       sync.Mutex
    jobs     map[string]*Job
    pending  jobHeap
    timer    *time.Timer
    maxJobs  int
    workers  chan struct{} // semaphore for concurrent job execution
}

type Job struct {
    ID       string
    Deadline time.Time
    Fn       func()
    index    int
    cancel   context.CancelFunc
}

type jobHeap []*Job

func (h jobHeap) Len() int { return len(h) }
func (h jobHeap) Less(i, j int) bool { return h[i].Deadline.Before(h[j].Deadline) }
func (h jobHeap) Swap(i, j int) {
    h[i], h[j] = h[j], h[i]
    h[i].index = i
    h[j].index = j
}
func (h *jobHeap) Push(x interface{}) {
    j := x.(*Job)
    j.index = len(*h)
    *h = append(*h, j)
}
func (h *jobHeap) Pop() interface{} {
    n := len(*h)
    j := (*h)[n-1]
    j.index = -1
    *h = (*h)[:n-1]
    return j
}

func New(maxJobs, maxConcurrent int) *Scheduler {
    return &Scheduler{
        jobs:    map[string]*Job{},
        maxJobs: maxJobs,
        workers: make(chan struct{}, maxConcurrent),
    }
}

func (s *Scheduler) Schedule(id string, at time.Time, fn func()) error {
    s.mu.Lock()
    defer s.mu.Unlock()
    if _, exists := s.jobs[id]; exists {
        return errors.New("duplicate job ID")
    }
    if len(s.jobs) >= s.maxJobs {
        return errors.New("scheduler full")
    }
    j := &Job{ID: id, Deadline: at, Fn: fn}
    s.jobs[id] = j
    heap.Push(&s.pending, j)
    s.armLocked()
    return nil
}

func (s *Scheduler) Cancel(id string) bool {
    s.mu.Lock()
    defer s.mu.Unlock()
    j, ok := s.jobs[id]
    if !ok {
        return false
    }
    delete(s.jobs, id)
    if j.index >= 0 {
        heap.Remove(&s.pending, j.index)
    }
    s.armLocked()
    return true
}

func (s *Scheduler) armLocked() {
    if s.pending.Len() == 0 {
        if s.timer != nil {
            s.timer.Stop()
            s.timer = nil
        }
        return
    }
    d := time.Until(s.pending[0].Deadline)
    if d < 0 {
        d = 0
    }
    if s.timer == nil {
        s.timer = time.AfterFunc(d, s.fire)
    } else {
        s.timer.Reset(d)
    }
}

func (s *Scheduler) fire() {
    s.mu.Lock()
    now := time.Now()
    var due []*Job
    for s.pending.Len() > 0 && !s.pending[0].Deadline.After(now) {
        j := heap.Pop(&s.pending).(*Job)
        delete(s.jobs, j.ID)
        due = append(due, j)
    }
    s.armLocked()
    s.mu.Unlock()
    for _, j := range due {
        s.runJob(j)
    }
}

func (s *Scheduler) runJob(j *Job) {
    select {
    case s.workers <- struct{}{}:
        defer func() { <-s.workers }()
        defer func() {
            if r := recover(); r != nil {
                // log and metric
            }
        }()
        j.Fn()
    default:
        // No worker available; drop or queue. For simplicity, drop.
    }
}