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