Artifact [a2f7b8e08c]

Artifact a2f7b8e08c9cb7770ed0d54b9b1ef9fa73a305ddb3663fe45b0a59c8fccdc459:

• File internal/obs/obs_test.go — part of check-in [17454ef71f] at 2026-08-31 15:37:28 on branch trunk — the footer names store wait the timing context missed

  A call on context.Background() carries no timer, so a page blocking six seconds on a warm pass reported 'ops 11.09s, zit 32.9ms' — and the ops panel's claim that ops minus zit is index work was false while it did. Overlap catches what attribution misses: subprocess busy time inside the render window, unioned, reported only when it exceeds what was already attributed. (user: quarry, size: 5142) [annotate] [blame] [check-ins using]

package obs

import (
	"testing"
	"time"
)

// The number that made this package necessary is CONCURRENCY, not
// duration: one slow listing is a performance note, and thirteen of the
// same listing at once is an incident. Live must count what is running,
// and peak must survive them finishing — otherwise the page shows zero
// after the fire is out and the operator learns nothing.
func TestLiveAndPeakSubprocessCount(t *testing.T) {
	r := NewRecorder(10, nil)
	for range 13 {
		r.Spawned()
	}
	if s := r.Snapshot(); s.LiveSubproc != 13 || s.PeakSubproc != 13 {
		t.Fatalf("during: live=%d peak=%d, want 13/13", s.LiveSubproc, s.PeakSubproc)
	}
	for range 13 {
		r.RecordSubprocess(Subprocess{Verb: "ls", Duration: time.Second})
	}
	s := r.Snapshot()
	if s.LiveSubproc != 0 {
		t.Errorf("after: live=%d, want 0", s.LiveSubproc)
	}
	if s.PeakSubproc != 13 {
		t.Errorf("after: peak=%d, want it to survive — the evidence outlives the incident", s.PeakSubproc)
	}
}

// A recorder that never goes negative, however the pairing breaks. A
// subprocess recorded without a matching Spawned is a bug, but it must
// not make the panel show a nonsense number.
func TestLiveNeverGoesNegative(t *testing.T) {
	r := NewRecorder(4, nil)
	r.RecordSubprocess(Subprocess{Verb: "cat"})
	if s := r.Snapshot(); s.LiveSubproc != 0 {
		t.Errorf("live=%d, want 0", s.LiveSubproc)
	}
}

// Slowest first by p95, which is the question the page answers. A mean
// would have hidden the 4.24s files page behind hundreds of 30ms ones.
func TestPathsRankByTailNotAverage(t *testing.T) {
	r := NewRecorder(500, nil)
	// A path that is usually fast and occasionally terrible.
	for range 99 {
		r.RecordRender(Render{Path: "/r/{repo}", Elapsed: 30 * time.Millisecond})
	}
	for range 20 {
		r.RecordRender(Render{Path: "/r/{repo}", Elapsed: 4 * time.Second})
	}
	// A path that is uniformly middling — a higher MEAN is not the point.
	for range 60 {
		r.RecordRender(Render{Path: "/timeline", Elapsed: 300 * time.Millisecond})
	}
	s := r.Snapshot()
	if len(s.Paths) != 2 {
		t.Fatalf("paths = %d, want 2", len(s.Paths))
	}
	if s.Paths[0].Path != "/r/{repo}" {
		t.Errorf("first = %q, want the one with the bad tail", s.Paths[0].Path)
	}
	if s.Paths[0].P95 < time.Second {
		t.Errorf("p95 = %v, want it to reflect the slow tail", s.Paths[0].P95)
	}
	if s.Paths[0].Max != 4*time.Second {
		t.Errorf("max = %v, want 4s", s.Paths[0].Max)
	}
	if s.Paths[0].N != 119 {
		t.Errorf("n = %d, want every render counted even though samples are windowed", s.Paths[0].N)
	}
}

// The sink is where history goes; the rings are what the page reads.
// A forge with no analytics store must still fill its panels.
func TestRingsWorkWithoutASink(t *testing.T) {
	r := NewRecorder(3, nil)
	r.RecordRender(Render{Path: "/a", Elapsed: time.Millisecond})
	if s := r.Snapshot(); len(s.Renders) != 1 {
		t.Fatalf("renders = %d, want 1 with a nil sink", len(s.Renders))
	}
}

type capture struct{ renders, subs int }

func (c *capture) Render(Render)         { c.renders++ }
func (c *capture) Subprocess(Subprocess) { c.subs++ }

func TestSinkReceivesEverythingTheRingsDo(t *testing.T) {
	c := &capture{}
	r := NewRecorder(2, c)
	// More than the ring holds: the ring is a window, the sink is not.
	for range 5 {
		r.RecordRender(Render{Path: "/a"})
		r.Spawned()
		r.RecordSubprocess(Subprocess{Verb: "ls"})
	}
	if c.renders != 5 || c.subs != 5 {
		t.Errorf("sink saw %d renders / %d subs, want 5/5 — the window must not truncate history",
			c.renders, c.subs)
	}
	if s := r.Snapshot(); len(s.Renders) != 2 {
		t.Errorf("ring held %d, want its cap of 2", len(s.Renders))
	}
}

// StoreBusy unions overlapping spans, for the same reason the timing
// package does: two concurrent half-second calls are half a second of
// waiting, not a second.
func TestStoreBusyUnionsOverlapAndClipsToTheWindow(t *testing.T) {
	r := NewRecorder(64, nil)
	base := time.Now()
	// Two concurrent 500ms calls inside the window.
	r.RecordSubprocess(Subprocess{At: base, Duration: 500 * time.Millisecond, Verb: "leaves"})
	r.RecordSubprocess(Subprocess{At: base.Add(100 * time.Millisecond), Duration: 400 * time.Millisecond, Verb: "info"})
	// One entirely before the window, one entirely after.
	r.RecordSubprocess(Subprocess{At: base.Add(-time.Hour), Duration: time.Second, Verb: "old"})
	r.RecordSubprocess(Subprocess{At: base.Add(time.Hour), Duration: time.Second, Verb: "later"})

	got := r.StoreBusy(base, base.Add(time.Second))
	if got < 450*time.Millisecond || got > 550*time.Millisecond {
		t.Errorf("StoreBusy = %v, want ~500ms (union, not sum, and clipped)", got)
	}
	// A call straddling the start counts only its part inside.
	r2 := NewRecorder(64, nil)
	r2.RecordSubprocess(Subprocess{At: base.Add(-500 * time.Millisecond), Duration: time.Second, Verb: "straddle"})
	if got := r2.StoreBusy(base, base.Add(time.Second)); got < 400*time.Millisecond || got > 600*time.Millisecond {
		t.Errorf("straddling span = %v, want ~500ms of it inside the window", got)
	}
	// An empty window is zero, not a panic.
	if got := r2.StoreBusy(base, base); got != 0 {
		t.Errorf("empty window = %v", got)
	}
}