0.2.79 - Slow api fixes
This commit is contained in:
ponzischeme89
@@ -0,0 +1,268 @@
|
||||
// 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
|
||||
}
|
||||
@@ -0,0 +1,135 @@
|
||||
package timing
|
||||
|
||||
import (
|
||||
"context"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
|
||||
// The breakdown is read at a glance beside a request line, so what matters about it is
|
||||
// the order and the shape rather than any one figure: the term an operator needs is the
|
||||
// first one.
|
||||
func TestBreakdownLeadsWithTheLargestStage(t *testing.T) {
|
||||
ctx, trace := New(context.Background())
|
||||
Record(ctx, StageRedis, 2*time.Millisecond)
|
||||
Record(ctx, StageEmby, 7810*time.Millisecond)
|
||||
Record(ctx, StageEmby, 300*time.Millisecond)
|
||||
Record(ctx, StageRows, 1400*time.Millisecond)
|
||||
Record(ctx, StageDB, 18*time.Millisecond)
|
||||
|
||||
got := trace.Breakdown()
|
||||
want := "emby=8.11s×2 rows=1.40s db=18ms redis=2ms"
|
||||
if got != want {
|
||||
t.Fatalf("breakdown = %q, want %q", got, want)
|
||||
}
|
||||
}
|
||||
|
||||
// A repeat is the interesting number and a single call is the ordinary case, so only the
|
||||
// repeat is printed. A route that should make one lookup and reports fourteen is the
|
||||
// finding, whatever its seconds say.
|
||||
func TestBreakdownMarksRepeatsOnly(t *testing.T) {
|
||||
ctx, trace := New(context.Background())
|
||||
Record(ctx, StageEmby, time.Millisecond)
|
||||
if got := trace.Breakdown(); strings.Contains(got, "×") {
|
||||
t.Fatalf("a single call should carry no multiplier: %q", got)
|
||||
}
|
||||
Record(ctx, StageEmby, time.Millisecond)
|
||||
if got := trace.Breakdown(); !strings.Contains(got, "×2") {
|
||||
t.Fatalf("a repeated call should say so: %q", got)
|
||||
}
|
||||
}
|
||||
|
||||
// Counts qualify the timings rather than competing with them, so they follow the stages
|
||||
// however large they get.
|
||||
func TestBreakdownPutsCountsAfterStages(t *testing.T) {
|
||||
ctx, trace := New(context.Background())
|
||||
Count(ctx, "miss")
|
||||
Record(ctx, StageEmby, 5*time.Millisecond)
|
||||
|
||||
got := trace.Breakdown()
|
||||
if !strings.HasPrefix(got, "emby=") || !strings.HasSuffix(got, "miss=1") {
|
||||
t.Fatalf("breakdown = %q, want a stage first and a count last", got)
|
||||
}
|
||||
}
|
||||
|
||||
// Everything here is called unconditionally from layers that have no idea whether they
|
||||
// are inside a request. An untraced context must cost a nil check and nothing else.
|
||||
func TestUntracedContextIsInert(t *testing.T) {
|
||||
ctx := context.Background()
|
||||
Record(ctx, StageEmby, time.Second)
|
||||
Count(ctx, "miss")
|
||||
Start(ctx, StageRows)()
|
||||
if From(ctx) != nil {
|
||||
t.Fatal("a plain context must carry no trace")
|
||||
}
|
||||
var absent *Trace
|
||||
if !absent.Empty() || absent.Breakdown() != "" {
|
||||
t.Fatal("a nil trace must report nothing rather than panicking")
|
||||
}
|
||||
}
|
||||
|
||||
// A request that touched nothing measurable prints no breakdown at all: an empty one
|
||||
// reads as a breakdown that failed.
|
||||
func TestEmptyTraceIsEmpty(t *testing.T) {
|
||||
_, trace := New(context.Background())
|
||||
if !trace.Empty() {
|
||||
t.Fatal("a fresh trace should be empty")
|
||||
}
|
||||
trace.Record(StageDB, time.Millisecond)
|
||||
if trace.Empty() {
|
||||
t.Fatal("a trace with a stage is not empty")
|
||||
}
|
||||
}
|
||||
|
||||
// Unattributed subtracts the largest stage rather than the sum of all of them, because
|
||||
// stages overlap — Home fans four Emby queries out at once — and a sum would routinely
|
||||
// exceed the request's own duration and report a negative remainder.
|
||||
func TestUnattributedSubtractsTheLargestStageOnly(t *testing.T) {
|
||||
_, trace := New(context.Background())
|
||||
trace.Record(StageEmby, 400*time.Millisecond)
|
||||
trace.Record(StageDB, 50*time.Millisecond)
|
||||
|
||||
if got := trace.Unattributed(500 * time.Millisecond); got != 100*time.Millisecond {
|
||||
t.Fatalf("unattributed = %v, want 100ms", got)
|
||||
}
|
||||
// Never negative. Concurrent calls summed into one stage can exceed the wall clock,
|
||||
// and a negative "elsewhere" would read as a broken measurement rather than as the
|
||||
// concurrency it actually is.
|
||||
trace.Record(StageEmby, 400*time.Millisecond)
|
||||
if got := trace.Unattributed(500 * time.Millisecond); got != 0 {
|
||||
t.Fatalf("unattributed = %v, want 0", got)
|
||||
}
|
||||
}
|
||||
|
||||
// A label is only ever a finer name for a stage the client would have recorded anyway,
|
||||
// so its absence must change nothing.
|
||||
func TestLabelFallsBackToTheClientsOwnStage(t *testing.T) {
|
||||
ctx := context.Background()
|
||||
if got := LabelFrom(ctx, StageEmby); got != StageEmby {
|
||||
t.Fatalf("unlabelled context = %q, want %q", got, StageEmby)
|
||||
}
|
||||
if got := LabelFrom(WithLabel(ctx, "emby.favourites"), StageEmby); got != "emby.favourites" {
|
||||
t.Fatalf("labelled context = %q, want emby.favourites", got)
|
||||
}
|
||||
if got := LabelFrom(WithLabel(ctx, ""), StageEmby); got != StageEmby {
|
||||
t.Fatalf("an empty label must not replace the stage, got %q", got)
|
||||
}
|
||||
}
|
||||
|
||||
// Sub-second times are read in milliseconds and longer ones in seconds. Duration's own
|
||||
// String prints nine digits of precision, which is unreadable in a column.
|
||||
func TestFormatDurationStaysNarrow(t *testing.T) {
|
||||
cases := map[time.Duration]string{
|
||||
0: "0ms",
|
||||
1500 * time.Microsecond: "2ms",
|
||||
999 * time.Millisecond: "999ms",
|
||||
time.Second: "1.00s",
|
||||
9512 * time.Millisecond: "9.51s",
|
||||
}
|
||||
for input, want := range cases {
|
||||
if got := formatDuration(input); got != want {
|
||||
t.Fatalf("formatDuration(%v) = %q, want %q", input, got, want)
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,80 @@
|
||||
package timing
|
||||
|
||||
import (
|
||||
"io"
|
||||
"net/http"
|
||||
"time"
|
||||
)
|
||||
|
||||
// Transport records every upstream HTTP call against a stage.
|
||||
//
|
||||
// It is a RoundTripper rather than a helper each client calls because there are eight
|
||||
// upstream clients here and the one thing they all genuinely share is that they make
|
||||
// HTTP requests. Wrapping the transport means a new integration is instrumented by
|
||||
// being constructed rather than by somebody remembering to measure it.
|
||||
//
|
||||
// The context it reads is the request's, so a call made outside a traced request —
|
||||
// a scheduled sync, a health probe — records nothing and costs one nil check.
|
||||
type Transport struct {
|
||||
Stage string
|
||||
Base http.RoundTripper
|
||||
}
|
||||
|
||||
func (t *Transport) RoundTrip(r *http.Request) (*http.Response, error) {
|
||||
base := t.Base
|
||||
if base == nil {
|
||||
base = http.DefaultTransport
|
||||
}
|
||||
trace := From(r.Context())
|
||||
if trace == nil {
|
||||
return base.RoundTrip(r)
|
||||
}
|
||||
stage := LabelFrom(r.Context(), t.Stage)
|
||||
began := time.Now()
|
||||
resp, err := base.RoundTrip(r)
|
||||
trace.Record(stage, time.Since(began))
|
||||
if err != nil || resp == nil || resp.Body == nil {
|
||||
return resp, err
|
||||
}
|
||||
// RoundTrip returns once the headers are in, and a home row is several hundred
|
||||
// kilobytes of JSON still on the wire at that point. Reading the body is part of
|
||||
// what the upstream cost, so the stage keeps accruing until the caller closes it —
|
||||
// otherwise the largest responses are the ones the breakdown under-reports.
|
||||
resp.Body = &timedBody{ReadCloser: resp.Body, trace: trace, stage: stage}
|
||||
return resp, nil
|
||||
}
|
||||
|
||||
type timedBody struct {
|
||||
io.ReadCloser
|
||||
trace *Trace
|
||||
stage string
|
||||
spent time.Duration
|
||||
done bool
|
||||
}
|
||||
|
||||
func (b *timedBody) Read(p []byte) (int, error) {
|
||||
began := time.Now()
|
||||
n, err := b.ReadCloser.Read(p)
|
||||
b.spent += time.Since(began)
|
||||
return n, err
|
||||
}
|
||||
|
||||
func (b *timedBody) Close() error {
|
||||
err := b.ReadCloser.Close()
|
||||
if !b.done {
|
||||
b.done = true
|
||||
b.trace.Record(b.stage, b.spent)
|
||||
}
|
||||
return err
|
||||
}
|
||||
|
||||
// Instrument wraps a client's transport in place. Called during construction, before
|
||||
// anything is serving, so it needs no synchronisation — the stance the Emby client's
|
||||
// other setters take.
|
||||
func Instrument(client *http.Client, stage string) *http.Client {
|
||||
if client == nil {
|
||||
return nil
|
||||
}
|
||||
client.Transport = &Transport{Stage: stage, Base: client.Transport}
|
||||
return client
|
||||
}
|
||||
Reference in New Issue
Block a user