Artifact [78855d5001]

Artifact 78855d5001e6229c9903eb9154e871cbee7e9284e0b5733bf9ca66d61d05b299:

• File internal/timing/timing.go — part of check-in [433a022052] at 2026-08-31 15:39:21 on branch trunk — the zit figure's count suffix is two bytes, not one

  The multiplication sign in 'zit 34.1ms×2' never matched a byte compare, so the duration parsed as zero and the store note appeared beside an identical zit figure — claiming a wait already accounted for. (user: quarry, size: 8854) [annotate] [blame] [check-ins using]

// Package timing accumulates where a request's time went, so the page
// can say so. Fossil publishes a single number ("generated in about
// 0.003s"); one number tells you a page is slow but not which layer to
// look at, and quarry's layers have wildly different costs — an index
// read is microseconds, a zit subprocess is milliseconds to seconds.
//
// The accumulator rides the request context. That is what makes it
// correct under concurrency: package-level counters would blend every
// in-flight request together, which is exactly the load this is meant to
// measure.
package timing

import (
	"context"
	"fmt"
	"sort"
	"strings"
	"sync"
	"time"
)

// Category names a layer. Kept as a small closed set rather than free
// text: the footer is a fixed-width place and an unbounded set of labels
// would make it unreadable.
type Category string

const (
	Zit Category = "zit" // subprocess calls to the store
	SQL Category = "sql" // index and OLTP queries
	// Ops is time inside op handlers, which CONTAINS zit and sql: the
	// registry is the seam every page's data passes through, and it is
	// one place rather than the hundreds a per-query wrapper would
	// touch. Reported as a container, never added to its contents.
	Ops   Category = "ops"
	Tmpl  Category = "tmpl" // template execution
	Chat  Category = "chat" // event-plane round trips
	HTTP  Category = "http" // outbound calls (notify, dagnats)
	Other Category = "other"
)

type entry struct {
	// spans are the intervals the category was BUSY, not a running
	// sum. quarry runs subprocesses concurrently on purpose — a diff
	// is two zit calls at once — and summing them printed more time
	// than the whole request took: "rendered in 410ms (zit 706.8ms×2)"
	// on tcl, and "79.94s (zit 159.05s×2)" on a cold one. A reader
	// cannot act on a number larger than the total; it reads as a bug
	// in the page rather than as two calls overlapping.
	spans []span
	n     int
}

// span is one observation's wall-clock interval.
type span struct{ start, end time.Time }

// busy is the length of the UNION of the spans: the wall time during
// which at least one call in this category was running. Two concurrent
// 350ms calls are 350ms of waiting, not 700ms.
func busy(spans []span) time.Duration {
	if len(spans) == 0 {
		return 0
	}
	sorted := make([]span, len(spans))
	copy(sorted, spans)
	sort.Slice(sorted, func(i, j int) bool { return sorted[i].start.Before(sorted[j].start) })
	var total time.Duration
	cur := sorted[0]
	for _, s := range sorted[1:] {
		if s.start.After(cur.end) { // a gap: bank the run and start over
			total += cur.end.Sub(cur.start)
			cur = s
			continue
		}
		if s.end.After(cur.end) {
			cur.end = s.end
		}
	}
	return total + cur.end.Sub(cur.start)
}

// Timing accumulates per-category durations and call counts.
type Timing struct {
	mu sync.Mutex
	by map[Category]*entry
}

type ctxKey struct{}

// With returns a context carrying a fresh accumulator, and the
// accumulator. A request that never calls this still works: Record on a
// context without one is a no-op, so instrumentation never depends on
// the caller having opted in.
func With(ctx context.Context) (context.Context, *Timing) {
	t := &Timing{by: map[Category]*entry{}}
	return context.WithValue(ctx, ctxKey{}, t), t
}

// From returns the context's accumulator, or nil.
func From(ctx context.Context) *Timing {
	t, _ := ctx.Value(ctxKey{}).(*Timing)
	return t
}

// Record adds one observation, ending now. Safe on a context with no
// accumulator and on a nil Timing, so call sites never need a guard.
//
// It takes the START rather than a duration: a duration cannot say
// whether two calls overlapped, and overlap is the whole question on a
// page that runs subprocesses concurrently.
func Record(ctx context.Context, c Category, start time.Time) {
	From(ctx).Add(c, start, time.Now())
}

// Track times fn and records it. The common shape at a call site.
func Track[T any](ctx context.Context, c Category, fn func() (T, error)) (T, error) {
	start := time.Now()
	v, err := fn()
	Record(ctx, c, start)
	return v, err
}

func (t *Timing) Add(c Category, start, end time.Time) {
	if t == nil {
		return
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	e := t.by[c]
	if e == nil {
		e = &entry{}
		t.by[c] = e
	}
	e.spans = append(e.spans, span{start, end})
	e.n++
}

// Breakdown renders the categories that actually did work, busiest
// first, as "zit 147ms×1, sql 3ms×4". The number is WALL time the
// category was busy, so "×2" beside 400ms means two calls overlapping
// inside 400ms of waiting, not 800ms of work. Categories with no calls are
// omitted rather than printed as zero: a footer listing every layer the
// server has would be noise on the pages that touch one of them.
//
// It deliberately does NOT include a total. The total is wall time,
// measured by the caller across the whole request; summing categories
// would under-report everything the layers do not cover and invite the
// reader to treat the difference as unaccounted rather than as
// uninstrumented.
func (t *Timing) Breakdown() string {
	if t == nil {
		return ""
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	type row struct {
		c    Category
		busy time.Duration
		n    int
	}
	rows := make([]row, 0, len(t.by))
	for c, e := range t.by {
		if e.n > 0 {
			rows = append(rows, row{c, busy(e.spans), e.n})
		}
	}
	sort.Slice(rows, func(i, j int) bool { return rows[i].busy > rows[j].busy })
	var b strings.Builder
	for i, r := range rows {
		if i > 0 {
			b.WriteString(", ")
		}
		fmt.Fprintf(&b, "%s %s", r.c, Format(r.busy))
		if r.n > 1 {
			fmt.Fprintf(&b, "×%d", r.n)
		}
	}
	return b.String()
}

// Category is the wall time one category was busy, for a caller that
// wants the numbers rather than the rendered string.
func (t *Timing) Category(c Category) time.Duration {
	if t == nil {
		return 0
	}
	t.mu.Lock()
	defer t.mu.Unlock()
	e := t.by[c]
	if e == nil {
		return 0
	}
	return busy(e.spans)
}

// Format words a duration for the footer at roughly three significant
// figures, so the number stays informative across the five orders of
// magnitude quarry spans — an index read is tens of microseconds and a
// cold listing is seconds.
//
// It does NOT floor at a millisecond. "<1ms" was true and useless: most
// pages are now sub-millisecond, so the floor collapsed the whole
// interesting range into one label and made an improvement from 900µs to
// 90µs invisible. Fossil's own footer has the mirror-image problem —
// it prints seconds to three decimals, so everything faster than a
// millisecond reads as "0.000s".
func Format(d time.Duration) string {
	us := float64(d) / float64(time.Microsecond)
	switch {
	case d <= 0:
		return "0"
	case us < 10: // 4.2µs
		return fmt.Sprintf("%.1fµs", us)
	case us < 1000: // 421µs
		return fmt.Sprintf("%.0fµs", us)
	case d < 10*time.Millisecond: // 4.21ms
		return fmt.Sprintf("%.2fms", float64(d)/float64(time.Millisecond))
	case d < time.Second: // 42.1ms
		return fmt.Sprintf("%.1fms", float64(d)/float64(time.Millisecond))
	default: // 4.21s
		return fmt.Sprintf("%.2fs", d.Seconds())
	}
}

// WithStoreBusy adds a store-wait note to a breakdown when the store was
// busy longer than this render's own attributed subprocess time.
//
// The two differ when a call runs on a detached context: the timer
// lives in the request's context, so a warm pass or a memo fill spawned
// with context.Background() is invisible to it while the render still
// waits. Reporting the overlap keeps the footer's other claim honest —
// that what is left after zit is index and OLTP work.
func WithStoreBusy(breakdown string, busy time.Duration) string {
	if busy <= 0 {
		return breakdown
	}
	// Only worth saying when it exceeds what was already attributed;
	// otherwise the existing zit figure already covers this wait.
	if attributed := zitFrom(breakdown); attributed >= busy {
		return breakdown
	}
	note := "store " + Format(busy)
	if breakdown == "" {
		return note
	}
	return breakdown + ", " + note
}

// zitFrom reads the zit total already present in a breakdown, so the
// store note is added only when it says something new.
func zitFrom(breakdown string) time.Duration {
	i := strings.Index(breakdown, "zit ")
	if i < 0 {
		return 0
	}
	rest := breakdown[i+len("zit "):]
	// Cut at the count suffix or the next category. Both terminators
	// are searched as STRINGS: the multiplication sign is two bytes in
	// UTF-8, so comparing it to a byte never matches and the duration
	// came back unparseable — which made the store note appear beside
	// an identical zit figure instead of staying quiet.
	for _, end := range []string{",", "×"} {
		if j := strings.Index(rest, end); j >= 0 {
			rest = rest[:j]
		}
	}
	d, err := time.ParseDuration(strings.TrimSpace(rest))
	if err != nil {
		return 0
	}
	return d
}