136 lines
4.8 KiB
Go
136 lines
4.8 KiB
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)
|
||
}
|
||
}
|
||
}
|