Artifact [24bfeaf894]

Artifact 24bfeaf894150b0eb5a10342d8d3c5cac435e2e5e596e72f27ba9fa60a42fce7:

• File internal/timing/timing_test.go — part of check-in [4aaf089616] at 2026-08-24 12:27:52 on branch timing-wall — timing: the footer reports wall time, not a sum of concurrent calls

  A diff is two zit subprocesses on purpose, run at once. Adding their durations printed more time than the whole request took — "rendered in 410.1ms (zit 706.8ms×2)", and "79.94s (zit 159.05s×2)" on a cold tcl page. A number larger than the total reads as a broken page rather than as two calls overlapping.

  Record now takes the start instant instead of a duration, because a duration cannot say whether two calls overlapped, and the union of the spans is what a reader actually waited. (user: dmestas, size: 3673) [annotate] [blame] [check-ins using] [more...]

package timing

import (
	"strings"
	"testing"
	"time"
)

// "<1ms" was true and useless. Most pages are sub-millisecond now, so
// the floor collapsed the interesting range into one label — an
// improvement from 900µs to 90µs was invisible. Fossil has the
// mirror-image problem: three decimals of seconds means everything
// faster than a millisecond prints as "0.000s".
func TestFormatKeepsPrecisionBelowAMillisecond(t *testing.T) {
	for _, tc := range []struct {
		d    time.Duration
		want string
	}{
		{4200 * time.Nanosecond, "4.2µs"},
		{421 * time.Microsecond, "421µs"},
		{999 * time.Microsecond, "999µs"},
		{4210 * time.Microsecond, "4.21ms"},
		{42100 * time.Microsecond, "42.1ms"},
		{536 * time.Millisecond, "536.0ms"},
		{2632 * time.Millisecond, "2.63s"},
		{0, "0"},
	} {
		if got := Format(tc.d); got != tc.want {
			t.Errorf("Format(%v) = %q, want %q", tc.d, got, tc.want)
		}
	}
	// The whole point: two sub-millisecond durations an order of
	// magnitude apart must not render identically.
	if Format(900*time.Microsecond) == Format(90*time.Microsecond) {
		t.Error("900µs and 90µs render the same — the floor is back")
	}
}

// The breakdown names only layers that did work, busiest first.
func TestBreakdownOrdersByCost(t *testing.T) {
	tm := &Timing{by: map[Category]*entry{}}
	t0 := time.Now()
	add := func(tm *Timing, c Category, from, to time.Duration) {
		tm.Add(c, t0.Add(from), t0.Add(to))
	}
	add(tm, SQL, 0, 2*time.Millisecond)
	add(tm, Zit, 0, 150*time.Millisecond)
	add(tm, Zit, 200*time.Millisecond, 300*time.Millisecond)

	got := tm.Breakdown()
	if !strings.HasPrefix(got, "zit ") {
		t.Errorf("breakdown = %q, want the costliest layer first", got)
	}
	if !strings.Contains(got, "×2") {
		t.Errorf("breakdown = %q, want the zit call count", got)
	}
	if strings.Contains(got, "chat") || strings.Contains(got, "http") {
		t.Errorf("breakdown = %q, want idle layers omitted", got)
	}
	if (*Timing)(nil).Breakdown() != "" {
		t.Error("nil Timing must render empty")
	}
}

// Concurrent calls are wall time, not a sum. quarry runs a diff as two
// zit subprocesses at once; adding them printed 706.8ms of zit inside a
// 410ms render, and 159.05s inside 79.94s on a cold tcl page — a number
// bigger than the total, which reads as a broken page rather than as
// two calls overlapping.
func TestConcurrentCallsCountOnceInWallTime(t *testing.T) {
	t0 := time.Now()
	add := func(tm *Timing, c Category, from, to time.Duration) {
		tm.Add(c, t0.Add(from), t0.Add(to))
	}

	overlap := &Timing{by: map[Category]*entry{}}
	add(overlap, Zit, 0, 400*time.Millisecond)
	add(overlap, Zit, 10*time.Millisecond, 390*time.Millisecond)
	if got := busy(overlap.by[Zit].spans); got != 400*time.Millisecond {
		t.Errorf("two overlapping calls = %v, want the 400ms a reader waited", got)
	}
	if b := overlap.Breakdown(); !strings.Contains(b, "×2") {
		t.Errorf("breakdown = %q, want both calls still counted", b)
	}

	// Serial calls still add up: the fix must not under-report work
	// that really did happen one after the other.
	serial := &Timing{by: map[Category]*entry{}}
	add(serial, Zit, 0, 100*time.Millisecond)
	add(serial, Zit, 200*time.Millisecond, 500*time.Millisecond)
	if got := busy(serial.by[Zit].spans); got != 400*time.Millisecond {
		t.Errorf("two serial calls = %v, want 400ms", got)
	}

	// A call wholly inside another contributes nothing extra.
	nested := &Timing{by: map[Category]*entry{}}
	add(nested, Zit, 0, 500*time.Millisecond)
	add(nested, Zit, 100*time.Millisecond, 200*time.Millisecond)
	if got := busy(nested.by[Zit].spans); got != 500*time.Millisecond {
		t.Errorf("nested call = %v, want 500ms", got)
	}
}