memby/server/internal/timing/timing_test.go

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