// 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 }