memby/server/internal/timing/timing.go

// Package timing answers "where did the time go" for one request.
//
// "The home screen took 9.5 seconds" is not actionable; "Emby 7.8s over four calls,
// row assembly 1.4s, Postgres 18ms" is. The gateway's slow requests are almost never
// slow in the gateway — they are waiting on Emby, on an *arr, on Postgres, or on
// several of those in a row — and until the request line could separate those, every
// investigation started by guessing.
//
// A trace is carried in the request context by pointer, the requestIdentity
// arrangement, so a layer four calls down can record against a trace the middleware
// created without anything in between having to know it exists. Everything here is a
// no-op when no trace is installed: a scheduled task, a health probe and every test
// call the same helpers and pay an interface-nil check.
//
// It measures *stages*, not spans in a tree. Most of what matters here is concurrent —
// Home fans four Emby queries out at once — so a total of wall-clock spans would
// exceed the request's own duration and mean nothing. What each stage reports is the
// summed busy time and the number of calls, and the call count is the half that finds
// duplicate work: "emby=7.8s ×14" on a page that should make two lookups is the
// finding, whatever the seconds say.
package timing

import (
	"context"
	"fmt"
	"sort"
	"strings"
	"sync"
	"time"
)

// Stage names. They are constants rather than free strings so a typo cannot quietly
// create a second column that never lines up with the first.
const (
	StageEmby          = "emby"
	StageDB            = "db"
	StageRedis         = "redis"
	StageSonarr        = "sonarr"
	StageRadarr        = "radarr"
	StageTracearr      = "tracearr"
	StageMDBList       = "mdblist"
	StageBazarr        = "bazarr"
	StageOpenSubtitles = "opensubtitles"
	StageIntegrations  = "integrations"

	// Gateway-side work, named for what a reader would call it rather than for the
	// function that does it.
	StageRows    = "rows"
	StageRank    = "rank"
	StageRatings = "ratings"
	StageHero    = "hero"
	StageEncode  = "encode"
	StageDecode  = "decode"
)

type stage struct {
	calls int
	total time.Duration
}

// Trace collects one request's stage totals. It is written from every goroutine a
// handler fans out to, so it is locked; the lock is held for a map write and nothing
// else, which is nothing beside the work being measured.
type Trace struct {
	mu      sync.Mutex
	stages  map[string]*stage
	counts  map[string]int
	started time.Time
}

type traceKey struct{}

// New installs a trace on ctx and returns both. The caller keeps the pointer so it can
// read the breakdown after the handler has returned.
func New(ctx context.Context) (context.Context, *Trace) {
	t := &Trace{
		stages:  make(map[string]*stage, 8),
		counts:  make(map[string]int, 4),
		started: time.Now(),
	}
	return context.WithValue(ctx, traceKey{}, t), t
}

// From returns the trace on ctx, or nil outside a traced request.
func From(ctx context.Context) *Trace {
	if ctx == nil {
		return nil
	}
	t, _ := ctx.Value(traceKey{}).(*Trace)
	return t
}

// Record adds one call's worth of time to a stage. Safe on a nil trace and on an
// untraced context, which is what lets call sites record unconditionally.
func Record(ctx context.Context, name string, d time.Duration) {
	From(ctx).Record(name, d)
}

func (t *Trace) Record(name string, d time.Duration) {
	if t == nil {
		return
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	s := t.stages[name]
	if s == nil {
		s = &stage{}
		t.stages[name] = s
	}
	s.calls++
	s.total += d
}

// Start begins a stage and returns the function that ends it. The idiom at the call
// site is `defer timing.Start(ctx, timing.StageRows)()`, which is why the returned
// func takes no argument: a stop that needed a value would be a stop somebody forgets
// to call on the error path.
func Start(ctx context.Context, name string) func() {
	t := From(ctx)
	if t == nil {
		return func() {}
	}
	began := time.Now()
	return func() { t.Record(name, time.Since(began)) }
}

// Count records a tally with no duration — a cache hit, a cache miss, a deduplicated
// upstream call. "Cache MISS" is the first thing anybody wants to know about a slow
// screen and it has no time of its own to report.
func Count(ctx context.Context, name string) {
	t := From(ctx)
	if t == nil {
		return
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	t.counts[name]++
}

// Empty reports whether anything was recorded. A request that touched nothing
// measurable should print no breakdown rather than an empty one, which reads as a
// breakdown that failed.
func (t *Trace) Empty() bool {
	if t == nil {
		return true
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	return len(t.stages) == 0 && len(t.counts) == 0
}

// Breakdown renders the trace as one scannable field:
//
//	emby=7.81s×4 rows=1.40s db=18ms×3 redis=2ms×2 encode=31ms miss=1
//
// Ordered by time spent, largest first, because the first term is the answer in almost
// every case. Counts follow the stages, since they qualify the timings rather than
// competing with them.
func (t *Trace) Breakdown() string {
	if t == nil {
		return ""
	}
	t.mu.Lock()
	defer t.mu.Unlock()

	type entry struct {
		name string
		s    stage
	}
	entries := make([]entry, 0, len(t.stages))
	for name, s := range t.stages {
		entries = append(entries, entry{name: name, s: *s})
	}
	sort.Slice(entries, func(i, j int) bool {
		if entries[i].s.total != entries[j].s.total {
			return entries[i].s.total > entries[j].s.total
		}
		return entries[i].name < entries[j].name
	})

	parts := make([]string, 0, len(entries)+len(t.counts))
	for _, e := range entries {
		part := e.name + "=" + formatDuration(e.s.total)
		// One call is the ordinary case and saying so on every term would make the
		// line harder to read, not easier. A repeat is the interesting number.
		if e.s.calls > 1 {
			part += fmt.Sprintf("×%d", e.s.calls)
		}
		parts = append(parts, part)
	}

	names := make([]string, 0, len(t.counts))
	for name := range t.counts {
		names = append(names, name)
	}
	sort.Strings(names)
	for _, name := range names {
		parts = append(parts, fmt.Sprintf("%s=%d", name, t.counts[name]))
	}
	return strings.Join(parts, " ")
}

// Unattributed is the request's own time less its largest stage.
//
// It is deliberately not called "gateway processing", and it is deliberately not the
// duration less the *sum* of the stages. Stages overlap — Home fans four Emby queries
// out at once — so a sum would routinely exceed the request's own duration and report a
// negative remainder. What this is instead is a lower bound on time nothing accounted
// for: zero means the evidence explains the request, and a large figure means something
// on the path is not being measured.
func (t *Trace) Unattributed(total time.Duration) time.Duration {
	if t == nil {
		return 0
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	var largest time.Duration
	for _, s := range t.stages {
		if s.total > largest {
			largest = s.total
		}
	}
	if remainder := total - largest; remainder > 0 {
		return remainder
	}
	return 0
}

// formatDuration keeps the column narrow: milliseconds under a second, two decimals
// above it. time.Duration's own String prints "7.812345678s", which is nine digits of
// precision nobody reading a request line has any use for.
func formatDuration(d time.Duration) string {
	if d < time.Second {
		return fmt.Sprintf("%dms", d.Round(time.Millisecond)/time.Millisecond)
	}
	return fmt.Sprintf("%.2fs", d.Seconds())
}

type labelKey struct{}

// WithLabel names the stage that upstream calls made under ctx record against, in place
// of the client's own.
//
// The reason it exists is Home: five Emby queries run concurrently, and a breakdown
// reading `emby=7.81s×5` says the launcher waited on Emby without saying which of the
// five it waited on — which is the whole of the next question. Labelled, the same
// request reports `emby.favourites=6.90s emby.resume=310ms emby.nextup=290ms …` and the
// answer is the first term.
//
// It is a context value rather than an argument because the thing being labelled is
// several layers below the thing that knows the name: the row's fetch closure knows it
// is the favourites row, and the transport that measures it is inside an HTTP client two
// packages away. A label is only ever a *finer* name for a stage the client would have
// recorded anyway, so nothing is lost where it is absent.
func WithLabel(ctx context.Context, label string) context.Context {
	if label == "" {
		return ctx
	}
	return context.WithValue(ctx, labelKey{}, label)
}

// LabelFrom returns the stage name in force for ctx, falling back to the client's own.
func LabelFrom(ctx context.Context, fallback string) string {
	if label, ok := ctx.Value(labelKey{}).(string); ok && label != "" {
		return label
	}
	return fallback
}