Artifact [f03a4af190]

Artifact f03a4af190b81b41f006322435f2008a7f84077c513467615e92b3c64dae4dd0:

• File internal/timing/timing.go — part of check-in [45bb75ade2] at 2026-08-17 21:26:48 on branch trunk — work: bound bulk operations; footer times keep their precision

  Nothing in quarry limited concurrency — every zit subprocess ran in the request goroutine with the arrival rate as the only bound. work.Lane is a concurrency limit plus a queue cap that SHEDS past it: a request accepted into a queue it cannot be served from consumes the capacity that would have served someone else.

  Wired to archive first, which buffers 256 MiB per request on an anonymous route. That is latent rather than live — archive 503s on zit#97 — which is why the bound belongs there now, so the endpoint is born bounded rather than acquiring a limit after someone finds it.

  Footer precision: '<1ms' was true and useless once most pages went sub-millisecond, collapsing the interesting range into one label. timing.Format keeps ~3 significant figures across five orders of magnitude, so 900µs and 90µs no longer read the same. Fossil has the mirror-image bug: three decimals of seconds prints everything faster than a millisecond as 0.000s. (user: dmestas, size: 4792) [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, Format(r.e.d))
		if r.e.n > 1 {
			fmt.Fprintf(&b, "×%d", r.e.n)
		}
	}
	return b.String()
}

// 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())
	}
}