269 lines
8.6 KiB
Go
269 lines
8.6 KiB
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
|
||
}
|