mesh-delivery: keep each delivery's time from its merge and answer times per class (hq ADR 0282, issue 382)
mesh/merge-gate fail: builds mesh-delivery → novox; no bus step; a manifest the change touches fails the module check: mesh-delivery claims mesh-delivery a…
mesh/repo-check fail: its merge-check.sh failed: files asking for a setting without saying whether it is trusted: 25
mesh/delivery superseded: a newer head of the same pull request

The operator's budget (a leaf module running everywhere within five minutes
of its merge, a core module within ten) cannot be held to without measuring
it. Each delivery now keeps its delivery time, class and phases from the
walk the controller says; 'times' answers the week's median and worst per
class, the deliveries over budget and their longest phase, and one
delivery's breakdown; 'deliveries' is headed by the same line. A phase the
walk could not measure stays unknown, never a zero. Measurement only.
This commit is contained in:
jochen
2026-10-10 20:14:19 +02:00
parent a14fa306f2
commit 404efb764b
6 changed files with 505 additions and 1 deletions
@@ -627,6 +627,9 @@ func (h *Holder) walkMoved(w Walk) {
h.creditCarried(m.Gate, w.ID, moved)
}
}
// And how long each delivery it answers took, once its end is known (novox/hq ADR 0282): measured, never
// acted on.
h.timeWalk(w)
}
// linkWalk records a walk on its delivery: what it is at, the commit it carries for it, and the machine steps
@@ -199,7 +199,25 @@ func tools(h *Holder, l *listening) []stdio.Tool {
"repository": str("owner/repository"), "group": str("a group's id (its branch name)"),
"all": map[string]any{"type": "string", "enum": []string{"true", "false"}}}},
Run: func(a map[string]any) (any, error) {
return h.Deliveries(strArg(a, "state"), strArg(a, "repository"), strArg(a, "group"), boolArg(a, "all")), nil
// Headed by the week's delivery times (novox/hq ADR 0282 decision 6).
return map[string]any{"times": h.TimesLine(),
"deliveries": h.Deliveries(strArg(a, "state"), strArg(a, "repository"), strArg(a, "group"), boolArg(a, "all"))}, nil
}},
{Name: seat + "times",
Description: "Delivery time (novox/hq ADR 0282): from a merge to every machine of its walk running the build. " +
"Each class's budget (a leaf module five minutes, a core module ten), the last days' median and worst, " +
"how many within and over, the newest delivery of each class, every delivery over its budget with its " +
"longest phase, and the delivered ones whose time is not known and why. Given a delivery's id, its time " +
"phase by phase: window, queued, word, build, send-first, judgement, send-rest, between-tiers, apply — " +
"each measured, unknown (never a zero) or none.",
Input: map[string]any{"type": "object", "properties": map[string]any{
"days": str("how many days back (default 7)"), "id": str("one delivery's id: its phases")}},
Run: func(a map[string]any) (any, error) {
days, err := intArg(a, "days")
if err != nil {
return nil, err
}
return h.Times(days, strArg(a, "id"))
}},
{Name: seat + "show",
Description: "One delivery or group whole: its delivery plan, every transition with when and why, the " +
@@ -78,6 +78,8 @@ type Delivery struct {
// of its branch; Steps the machines it reached.
Walk *WalkSeen `json:"walk,omitempty"`
Steps []Step `json:"steps,omitempty"`
// Time is its delivery time, class and phases (novox/hq ADR 0282), once its walk's end is known.
Time *DeliveryTime `json:"delivery_time,omitempty"`
// LetGo is when this owner asked the controller to start its walk, and why.
LetGo time.Time `json:"let_go"`
LetGoWhy string `json:"let_go_why,omitempty"`
@@ -307,6 +309,9 @@ type Walk struct {
Revision int64 `json:"revision"`
Release *WalkRelease `json:"release,omitempty"`
Delivery *WalkDelivery `json:"delivery,omitempty"`
// Phases is the walk's time from its merge, phase by phase, as the controller works it out (novox/hq ADR
// 0282): what a delivery's time is kept from. Absent from a controller that does not say it.
Phases *WalkPhases `json:"phases,omitempty"`
}
// WalkModule is one module of a walk.
@@ -0,0 +1,320 @@
package main
import (
"fmt"
"slices"
"sort"
"strings"
"time"
)
// Delivery time and delivery budgets (novox/hq ADR 0282 decisions 1 and 6, issue 382): a delivery's time runs
// from its merge to every machine of its walk's rest reporting the build applied. The controller works out the
// walk's phases (its `delivery-walks` and `plan-moved` say them); this owner keeps, on each delivery, its own
// delivery time from its own merge, its class and its phases, and `times` answers the week's median and worst
// per class against its budget. Measurement only: nothing here holds, releases or changes a delivery.
// The budgets by class (ADR 0282 decision 1).
var budgets = map[string]time.Duration{"leaf": 5 * time.Minute, "core": 10 * time.Minute}
// classes in the order `times` says them.
var classes = []string{"leaf", "core"}
// WalkPhases is a walk's time phase by phase, as the controller says it (mesh-controller inventory.WalkPhases).
type WalkPhases struct {
Class string `json:"class,omitempty"`
From *time.Time `json:"from,omitempty"`
End *time.Time `json:"end,omitempty"`
TotalMS int64 `json:"total_ms,omitempty"`
UnknownMS int64 `json:"unknown_ms,omitempty"`
Phases []WalkPhase `json:"phases"`
Silent []string `json:"silent,omitempty"`
Said string `json:"said"`
Merges []MergeStart `json:"merges,omitempty"`
}
// MergeStart is one merge a walk answers and when it was made.
type MergeStart struct {
Repository string `json:"repository"`
Commit string `json:"commit"`
Merged time.Time `json:"merged"`
}
// WalkPhase is one phase of a walk: measured, unknown (never a zero), none (it did not happen) or open.
type WalkPhase struct {
Name string `json:"name"`
Tier int `json:"tier"`
State string `json:"state"`
Start *time.Time `json:"start,omitempty"`
End *time.Time `json:"end,omitempty"`
TookMS int64 `json:"took_ms,omitempty"`
Took string `json:"took,omitempty"`
Said string `json:"said,omitempty"`
}
const (
phaseMeasured = "measured"
phaseUnknown = "unknown"
)
// DeliveryTime is a delivery's time, kept on it once its walk's end is known.
type DeliveryTime struct {
Walk string `json:"walk"`
Class string `json:"class"`
// From is its own merge; End when every machine of its walk's rest reported the build applied.
From time.Time `json:"from"`
End time.Time `json:"end"`
TookMS int64 `json:"took_ms"`
Took string `json:"took"`
BudgetMS int64 `json:"budget_ms,omitempty"`
Over bool `json:"over,omitempty"`
Longest string `json:"longest,omitempty"`
UnknownMS int64 `json:"unknown_ms,omitempty"`
Phases []WalkPhase `json:"phases"`
Silent []string `json:"silent,omitempty"`
}
// timeOf is a delivery's time from its walk's phases; nil while the walk's end is not known.
func timeOf(d *Delivery, w Walk) *DeliveryTime {
p := w.Phases
if p == nil || p.End == nil || p.From == nil {
return nil
}
from := d.MergedAt
for _, m := range p.Merges {
if from.IsZero() && strings.EqualFold(m.Repository, d.Repository) && sameCommit(m.Commit, d.MergedAs) {
from = m.Merged
}
}
if from.IsZero() {
from = *p.From
}
from = from.Truncate(time.Millisecond)
t := &DeliveryTime{Walk: w.ID, Class: p.Class, From: from, End: *p.End, UnknownMS: p.UnknownMS,
Phases: slices.Clone(p.Phases), Silent: p.Silent}
// The walk's time runs from its earliest merge; this delivery's from its own: the first phase with an end
// starts there, so the phases and the unknown time still add up to the total.
for i, ph := range t.Phases {
if ph.End == nil {
continue
}
if ph.State == phaseMeasured {
start := from
ph.Start = &start
ph.TookMS = ph.End.Sub(from).Milliseconds()
ph.Took = ph.End.Sub(from).Round(100 * time.Millisecond).String()
t.Phases[i] = ph
} else {
t.UnknownMS += p.From.Sub(from).Milliseconds()
}
break
}
took := t.End.Sub(from)
t.TookMS, t.Took = took.Milliseconds(), took.Round(time.Second).String()
if b, ok := budgets[t.Class]; ok {
t.BudgetMS, t.Over = b.Milliseconds(), took > b
}
t.Longest = longestOf(t.Phases)
return t
}
// longestOf is the longest measured phase, as words: "judgement (tier 0) 2m29s".
func longestOf(phases []WalkPhase) string {
best := -1
for i, ph := range phases {
if ph.State == phaseMeasured && (best < 0 || ph.TookMS > phases[best].TookMS) {
best = i
}
}
if best < 0 {
return ""
}
ph := phases[best]
name := ph.Name
if ph.Tier >= 0 {
name = fmt.Sprintf("%s (tier %d)", ph.Name, ph.Tier)
}
return name + " " + (time.Duration(ph.TookMS) * time.Millisecond).Round(time.Second).String()
}
// timeWalk keeps, on every delivery the walk answers, its delivery time once the walk's end is known; a delivery
// whose time did not change is not written again (issue 326).
func (h *Holder) timeWalk(w Walk) {
if w.Phases == nil || w.Phases.End == nil {
return
}
for _, d := range h.deliveries {
if d.Walk == nil || d.Walk.ID != w.ID {
continue
}
t := timeOf(d, w)
if t == nil || (d.Time != nil && d.Time.TookMS == t.TookMS && d.Time.End.Equal(t.End) && d.Time.Walk == t.Walk &&
d.Time.Class == t.Class && d.Time.UnknownMS == t.UnknownMS && d.Time.Longest == t.Longest) {
continue
}
d.Time = t
h.keep(d)
}
}
// TimesClass is one class's line of `times`.
type TimesClass struct {
Class string `json:"class"`
Budget string `json:"budget"`
BudgetMS int64 `json:"budget_ms"`
Count int `json:"count"`
Median string `json:"median,omitempty"`
MedianMS int64 `json:"median_ms,omitempty"`
Worst string `json:"worst,omitempty"`
WorstMS int64 `json:"worst_ms,omitempty"`
WorstID string `json:"worst_id,omitempty"`
Within int `json:"within"`
Over int `json:"over"`
Latest *TimesLatest `json:"latest,omitempty"`
}
// TimesLatest is a delivery as `times` names it: the newest of a class, or one over its budget.
type TimesLatest struct {
ID string `json:"id"`
Class string `json:"class,omitempty"`
TookMS int64 `json:"took_ms"`
Took string `json:"took"`
Over bool `json:"over,omitempty"`
Longest string `json:"longest,omitempty"`
Landed string `json:"landed"`
}
// TimesAnswer is `times`.
type TimesAnswer struct {
Days int `json:"days"`
Line string `json:"line"`
Classes []TimesClass `json:"classes"`
Over []TimesLatest `json:"over,omitempty"`
// Unknown are the deliveries delivered in the window whose time is not known, and why it is not: at most
// unknownShown of them, UnknownCount all.
Unknown []string `json:"unknown,omitempty"`
UnknownCount int `json:"unknown_count,omitempty"`
}
// unknownShown is how many deliveries with no known time `times` names.
const unknownShown = 20
// Times is the `times` verb: each class's budget, the last days' median and worst delivery time, and every
// delivery over its budget with its longest phase; or, given a delivery's id, its time phase by phase.
func (h *Holder) Times(days int, id string) (any, error) {
h.mu.Lock()
defer h.mu.Unlock()
if id != "" {
d := h.deliveries[id]
if d == nil {
return nil, fmt.Errorf("no delivery %q: `deliveries` lists them", id)
}
if d.Time == nil {
why := "its walk's end is not known yet"
if d.Walk == nil {
why = "no walk answers it"
} else if s, ok := h.walks[d.Walk.ID]; ok && s.walk.Phases != nil {
why = s.walk.Phases.Said
}
return map[string]any{"delivery": id, "state": d.State, "time": nil, "why": why}, nil
}
return map[string]any{"delivery": id, "state": d.State, "time": d.Time}, nil
}
return h.times(days), nil
}
// times is the answer for the last days, under the lock.
func (h *Holder) times(days int) TimesAnswer {
if days <= 0 {
days = 7
}
since := h.Now().Add(-time.Duration(days) * 24 * time.Hour)
a := TimesAnswer{Days: days}
took := map[string][]*Delivery{}
for _, d := range h.deliveries {
if d.Time == nil {
if (d.State == Delivered || d.State == Covered) && d.Since.After(since) {
why := "its walk's end is not known"
if d.Walk != nil {
if s, ok := h.walks[d.Walk.ID]; ok && s.walk.Phases != nil && s.walk.Phases.Said != "" {
why = s.walk.Phases.Said
}
}
a.Unknown = append(a.Unknown, d.ID+": "+why)
}
continue
}
if d.Time.End.Before(since) {
continue
}
took[d.Time.Class] = append(took[d.Time.Class], d)
}
sort.Strings(a.Unknown)
a.UnknownCount = len(a.Unknown)
if len(a.Unknown) > unknownShown {
a.Unknown = a.Unknown[:unknownShown]
}
var line []string
for _, class := range classes {
c := TimesClass{Class: class, Budget: budgets[class].String(), BudgetMS: budgets[class].Milliseconds()}
ds := took[class]
sort.Slice(ds, func(i, j int) bool { return ds[i].Time.TookMS < ds[j].Time.TookMS })
c.Count = len(ds)
for _, d := range ds {
if d.Time.Over {
c.Over++
a.Over = append(a.Over, latestOf(d))
} else {
c.Within++
}
if c.Latest == nil || d.Time.End.After(mustLanded(c.Latest)) {
l := latestOf(d)
c.Latest = &l
}
}
if len(ds) > 0 {
med := median(ds)
c.MedianMS, c.Median = med.Milliseconds(), med.Round(time.Second).String()
worst := ds[len(ds)-1]
c.WorstMS, c.Worst, c.WorstID = worst.Time.TookMS, worst.Time.Took, worst.ID
line = append(line, fmt.Sprintf("%s: median %s, worst %s, %d of %d within %s", class, c.Median, c.Worst,
c.Within, c.Count, c.Budget))
} else {
line = append(line, fmt.Sprintf("%s: no delivery with a known time", class))
}
a.Classes = append(a.Classes, c)
}
sort.Slice(a.Over, func(i, j int) bool { return a.Over[i].Landed > a.Over[j].Landed })
a.Line = fmt.Sprintf("delivery time over %d day(s) — %s", days, strings.Join(line, "; "))
if a.UnknownCount > 0 {
a.Line += fmt.Sprintf("; %d delivered with no known time", a.UnknownCount)
}
return a
}
func latestOf(d *Delivery) TimesLatest {
return TimesLatest{ID: d.ID, Class: d.Time.Class, TookMS: d.Time.TookMS, Took: d.Time.Took, Over: d.Time.Over,
Longest: d.Time.Longest, Landed: d.Time.End.UTC().Format(time.RFC3339)}
}
func mustLanded(l *TimesLatest) time.Time {
t, _ := time.Parse(time.RFC3339, l.Landed)
return t
}
// median of deliveries sorted by their time.
func median(ds []*Delivery) time.Duration {
n := len(ds)
ms := ds[n/2].Time.TookMS
if n%2 == 0 {
ms = (ds[n/2-1].Time.TookMS + ds[n/2].Time.TookMS) / 2
}
return time.Duration(ms) * time.Millisecond
}
// TimesLine is the one line `deliveries` heads its list with.
func (h *Holder) TimesLine() string {
h.mu.Lock()
defer h.mu.Unlock()
return h.times(7).Line
}
@@ -0,0 +1,157 @@
package main
import (
"strings"
"testing"
"time"
)
// novox/hq ADR 0282 (issue 382): a delivery keeps its delivery time, class and phases from its walk, from its
// own merge; `times` answers each class's median and worst against its budget. Measurement only.
func ms(t time.Time) *time.Time { return &t }
// phasesOf is a walk's phases as the controller says them: its earliest merge at from, then each phase of the
// given lengths one after the other, the last ending the walk.
func phasesOf(class string, from time.Time, lengths ...struct {
name string
d time.Duration
}) *WalkPhases {
p := &WalkPhases{Class: class, From: ms(from)}
at := from
for _, l := range lengths {
start := at
at = at.Add(l.d)
p.Phases = append(p.Phases, WalkPhase{Name: l.name, Tier: -1, State: phaseMeasured, Start: ms(start), End: ms(at),
TookMS: l.d.Milliseconds()})
}
p.End = ms(at)
p.TotalMS = at.Sub(from).Milliseconds()
return p
}
type ph = struct {
name string
d time.Duration
}
// walkedOnce is a merge walked to the end, the walk's phases given: its delivery's id.
func walkedOnce(w *world, number int, head, merge string, phases *WalkPhases) string {
w.t.Helper()
repo := "novox/mesh-catalog"
p := pr(repo, number, head, "feat/x")
w.h.PullUpdated(p)
w.h.Checked(verdictMoving(repo, number, head, "app"))
w.h.PullMerged(mergedAt(p, merge, phases.From.Add(10*time.Second)))
walk := aWalk("plan-"+merge[:6], repo, merge, false)
walk.Delivery = &WalkDelivery{Merges: []WalkMerge{{Repository: repo, Commit: merge}}}
w.h.WalkMoved(w.ctl.put(walk))
w.settleAll()
walk = w.ctl.walk(walk.ID)
walk.State, walk.Revision = walkDone, walk.Revision+1
walk.Modules = map[string]*WalkModule{"app": {State: "built", SentAt: phases.End}}
walk.Phases = phases
w.h.WalkMoved(w.ctl.put(walk))
w.settleAll()
return IDOf(repo, head)
}
// A delivery's time runs from its own merge — ten seconds after the walk's earliest — to its walk's end, and its
// phases still add up to it.
func TestADeliveryKeepsItsTimeFromItsOwnMerge(t *testing.T) {
w := newWorld(t)
from := t0.Add(time.Minute)
id := walkedOnce(w, 7, "head7", "merge7aaaa", phasesOf("leaf", from, ph{"window", 90 * time.Second},
ph{"queued", 5 * time.Second}, ph{"build", 25 * time.Second}, ph{"judgement", 150 * time.Second},
ph{"apply", 20 * time.Second}))
d := w.delivery(id)
if d.Time == nil {
t.Fatalf("no delivery time kept: %+v", d)
}
if d.Time.TookMS != (280*time.Second).Milliseconds() || d.Time.Class != "leaf" || d.Time.Over {
t.Fatalf("time %dms (want 280000, from its own merge), class %s, over %v", d.Time.TookMS, d.Time.Class, d.Time.Over)
}
var sum int64
for _, p := range d.Time.Phases {
if p.State == phaseMeasured {
sum += p.TookMS
}
}
if sum+d.Time.UnknownMS != d.Time.TookMS {
t.Fatalf("the phases add up to %dms + %dms unknown, its time is %dms", sum, d.Time.UnknownMS, d.Time.TookMS)
}
if d.Time.Phases[0].TookMS != 80000 || !strings.HasPrefix(d.Time.Longest, "judgement") {
t.Fatalf("its window starts at its own merge (80s), longest judgement: %+v %s", d.Time.Phases[0], d.Time.Longest)
}
// Seen again, unchanged: not written again (issue 326).
before := w.store.puts
w.h.Reconcile()
w.settleAll()
if w.store.puts != before {
t.Fatalf("a delivery whose time did not change was written again")
}
}
// A walk whose end is not known gives no time; a phase unknown in the walk stays unknown, never a zero.
func TestNoEndNoTime(t *testing.T) {
w := newWorld(t)
p := phasesOf("core", t0, ph{"window", time.Minute}, ph{"build", time.Minute})
p.End, p.TotalMS = nil, 0
p.Phases = append(p.Phases, WalkPhase{Name: "apply", Tier: -1, State: phaseUnknown, Said: "waiting for ace"})
p.Said = "its end is unknown: apply (waiting for ace)"
id := walkedOnce(w, 8, "head8", "merge8bbbb", p)
if d := w.delivery(id); d.Time != nil {
t.Fatalf("a time without an end: %+v", d.Time)
}
got, err := w.h.Times(0, id)
if err != nil || !strings.Contains(mustString(got), "waiting for ace") {
t.Fatalf("the delivery's time says why it is not known: %v %v", got, err)
}
a := w.h.times(7)
if len(a.Unknown) != 1 || !strings.Contains(a.Unknown[0], "waiting for ace") {
t.Fatalf("a delivered delivery with no known time is said: %+v", a.Unknown)
}
}
// `times`: each class's median, worst, within and over its budget, its newest delivery, and every delivery over.
func TestTimesSaysEachClassAgainstItsBudget(t *testing.T) {
w := newWorld(t)
leaf := func(n int, d time.Duration, at time.Duration) string {
return walkedOnce(w, n, "head"+string(rune('a'+n)), "merge"+string(rune('a'+n))+"zzzz",
phasesOf("leaf", t0.Add(at), ph{"window", 10 * time.Second}, ph{"judgement", d}))
}
leaf(1, 2*time.Minute, 0)
leaf(2, 4*time.Minute, time.Hour)
over := leaf(3, 6*time.Minute, 2*time.Hour)
walkedOnce(w, 4, "headcore", "mergekore1", phasesOf("core", t0.Add(3*time.Hour), ph{"judgement", 9 * time.Minute}))
w.later(4 * time.Hour)
a := w.h.times(7)
if len(a.Classes) != 2 || a.Classes[0].Class != "leaf" {
t.Fatalf("classes: %+v", a.Classes)
}
l := a.Classes[0]
// Each delivery's time is from its own merge, ten seconds after the walk's: 2m, 4m, 6m.
if l.Count != 3 || l.Within != 2 || l.Over != 1 || l.MedianMS != (4*time.Minute).Milliseconds() ||
l.WorstMS != (6*time.Minute).Milliseconds() || l.WorstID != over {
t.Fatalf("leaf: %+v", l)
}
if l.Latest == nil || l.Latest.ID != over || !l.Latest.Over || !strings.HasPrefix(l.Latest.Longest, "judgement") {
t.Fatalf("the newest leaf delivery: %+v", l.Latest)
}
if c := a.Classes[1]; c.Count != 1 || c.Over != 0 || c.Latest == nil || c.Latest.Over {
t.Fatalf("core within ten minutes: %+v", c)
}
if len(a.Over) != 1 || a.Over[0].ID != over {
t.Fatalf("over: %+v", a.Over)
}
if !strings.Contains(a.Line, "leaf: median 4m0s, worst 6m0s, 2 of 3 within 5m0s") {
t.Fatalf("the line: %s", a.Line)
}
// Past the window, nothing.
w.later(8 * 24 * time.Hour)
if a := w.h.times(7); a.Classes[0].Count != 0 || a.Classes[0].Latest != nil {
t.Fatalf("deliveries older than the window are not counted: %+v", a.Classes[0])
}
}
func mustString(v any) string { return string(mustJSON(v)) }
+1
View File
@@ -8,6 +8,7 @@
"scope": "mesh",
"serves": [
"deliveries",
"times",
"show",
"groups",
"what-if",