Skip to content
quarry Artifact [310f708af4]
Login

Artifact [310f708af4]

Check-ins Using Download Hex

Artifact 310f708af419130f10272802ca36393923b249bb22e8fa97b5702dc1729e5d0e:

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

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