Artifact [7635c6e14e]

Artifact 7635c6e14e559d6f992de5c3ccf5148ae676b4ed9ff6c2fef0fabb449d31ffc8:

• File internal/timing/timing.go — part of check-in [85b9909d1c] at 2026-08-17 20:51:22 on branch trunk — web: report where a request's time went, not just how long

  The footer said 'rendered in 344ms'; it now says 'rendered in 344ms (zit 270ms)'. One number says a page is slow, not which layer to look at, and quarry's layers differ by three orders of magnitude — an index read is microseconds, zit ls --long on tk is 2.6 seconds.

  The accumulator rides the request context, which is what makes it correct under load: package-level counters would blend concurrent requests together, and concurrency is what this exists to measure.

  zit read calls take a context now and use exec.CommandContext, so an abandoned request kills its subprocess instead of leaving it to finish a 2.6-second listing nobody will read.

  SQL is not instrumented yet; the index does not take a context. (user: dmestas, size: 4032) [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
	Chat  Category = "chat"  // event-plane round trips
	HTTP  Category = "http"  // outbound calls (notify, dagnats)
	Other Category = "other"
)

type entry struct {
	d time.Duration
	n int
}

// 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. Safe on a context with no accumulator and
// on a nil Timing, so call sites never need a guard.
func Record(ctx context.Context, c Category, d time.Duration) {
	From(ctx).Add(c, d)
}

// 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, time.Since(start))
	return v, err
}

func (t *Timing) Add(c Category, d time.Duration) {
	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.d += d
	e.n++
}

// Breakdown renders the categories that actually did work, busiest
// first, as "zit 147ms×1, sql 3ms×4". 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
		e entry
	}
	rows := make([]row, 0, len(t.by))
	for c, e := range t.by {
		if e.n > 0 {
			rows = append(rows, row{c, *e})
		}
	}
	sort.Slice(rows, func(i, j int) bool { return rows[i].e.d > rows[j].e.d })
	var b strings.Builder
	for i, r := range rows {
		if i > 0 {
			b.WriteString(", ")
		}
		fmt.Fprintf(&b, "%s %s", r.c, short(r.e.d))
		if r.e.n > 1 {
			fmt.Fprintf(&b, "×%d", r.e.n)
		}
	}
	return b.String()
}

// short words a duration the way the footer needs it: whole milliseconds
// once past one, and a floor below that rather than a spuriously precise
// fraction of a millisecond.
func short(d time.Duration) string {
	switch {
	case d < time.Millisecond:
		return "<1ms"
	case d < time.Second:
		return fmt.Sprintf("%dms", d.Milliseconds())
	default:
		return fmt.Sprintf("%.2fs", d.Seconds())
	}
}