From 404efb764b2264e1c0afde26c3d6559fa001f512 Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 20:14:19 +0200 Subject: [PATCH 1/4] mesh-delivery: keep each delivery's time from its merge and answer times per class (hq ADR 0282, issue 382) 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. --- .../mesh-delivery/cmd/mesh-delivery/holder.go | 3 + .../mesh-delivery/cmd/mesh-delivery/main.go | 20 +- .../mesh-delivery/cmd/mesh-delivery/model.go | 5 + .../mesh-delivery/cmd/mesh-delivery/times.go | 320 ++++++++++++++++++ .../cmd/mesh-delivery/times_test.go | 157 +++++++++ modules/mesh-delivery/module.json | 1 + 6 files changed, 505 insertions(+), 1 deletion(-) create mode 100644 modules/mesh-delivery/cmd/mesh-delivery/times.go create mode 100644 modules/mesh-delivery/cmd/mesh-delivery/times_test.go diff --git a/modules/mesh-delivery/cmd/mesh-delivery/holder.go b/modules/mesh-delivery/cmd/mesh-delivery/holder.go index efd79a18..1627f89f 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/holder.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/holder.go @@ -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 diff --git a/modules/mesh-delivery/cmd/mesh-delivery/main.go b/modules/mesh-delivery/cmd/mesh-delivery/main.go index be88762a..6fe80a48 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/main.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/main.go @@ -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 " + diff --git a/modules/mesh-delivery/cmd/mesh-delivery/model.go b/modules/mesh-delivery/cmd/mesh-delivery/model.go index 7104748c..5f9964fb 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/model.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/model.go @@ -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. diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times.go b/modules/mesh-delivery/cmd/mesh-delivery/times.go new file mode 100644 index 00000000..df1b37e8 --- /dev/null +++ b/modules/mesh-delivery/cmd/mesh-delivery/times.go @@ -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 +} diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go new file mode 100644 index 00000000..cfc800ee --- /dev/null +++ b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go @@ -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)) } diff --git a/modules/mesh-delivery/module.json b/modules/mesh-delivery/module.json index 9c7d8d93..1215633c 100644 --- a/modules/mesh-delivery/module.json +++ b/modules/mesh-delivery/module.json @@ -8,6 +8,7 @@ "scope": "mesh", "serves": [ "deliveries", + "times", "show", "groups", "what-if", From 383e698254627c68fe4d629e290cdf401e54feeb Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 20:16:46 +0200 Subject: [PATCH 2/4] mesh-delivery: rebase only a first phase that starts at the walk's merge; a class without a budget is said unknown --- modules/mesh-delivery/cmd/mesh-delivery/times.go | 9 ++++++++- .../mesh-delivery/cmd/mesh-delivery/times_test.go | 13 +++++++++++++ 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times.go b/modules/mesh-delivery/cmd/mesh-delivery/times.go index df1b37e8..b65172a3 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times.go @@ -98,7 +98,7 @@ func timeOf(d *Delivery, w Walk) *DeliveryTime { if ph.End == nil { continue } - if ph.State == phaseMeasured { + if ph.State == phaseMeasured && ph.Start != nil && ph.Start.Equal(*p.From) { start := from ph.Start = &start ph.TookMS = ph.End.Sub(from).Milliseconds() @@ -140,6 +140,9 @@ func longestOf(phases []WalkPhase) 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 s, ok := h.walks[w.ID]; ok && s.walk.Revision > w.Revision { + w = s.walk // an older record arriving late: the newest says the time + } if w.Phases == nil || w.Phases.End == nil { return } @@ -247,6 +250,10 @@ func (h *Holder) times(days int) TimesAnswer { if d.Time.End.Before(since) { continue } + if _, ok := budgets[d.Time.Class]; !ok { + a.Unknown = append(a.Unknown, fmt.Sprintf("%s: took %s, its class %q has no budget", d.ID, d.Time.Took, d.Time.Class)) + continue + } took[d.Time.Class] = append(took[d.Time.Class], d) } sort.Strings(a.Unknown) diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go index cfc800ee..98f08a6f 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go @@ -83,6 +83,19 @@ func TestADeliveryKeepsItsTimeFromItsOwnMerge(t *testing.T) { 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) } + // Its own merge after a first phase whose start is unknown: the unknown time moves, the sum holds. + p := phasesOf("leaf", from, ph{"window", 90 * time.Second}, ph{"build", 30 * time.Second}) + p.Phases[0] = WalkPhase{Name: "window", Tier: -1, State: phaseUnknown, End: p.Phases[0].End} + p.UnknownMS = 90000 + dt := timeOf(&Delivery{MergedAt: from.Add(10 * time.Second)}, Walk{ID: "w", Phases: p}) + if dt.UnknownMS != 80000 || dt.TookMS != 110000 { + t.Fatalf("unknown first phase: %+v", dt) + } + // Exactly its budget is within it. + p = phasesOf("leaf", from, ph{"build", 5*time.Minute + 10*time.Second}) + if dt := timeOf(&Delivery{MergedAt: from.Add(10 * time.Second)}, Walk{ID: "w", Phases: p}); dt.Over || dt.TookMS != 300000 { + t.Fatalf("five minutes is within a leaf's budget: %+v", dt) + } // Seen again, unchanged: not written again (issue 326). before := w.store.puts w.h.Reconcile() From 662c4105d3673b5cfec260db83f57891664cc83b Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 20:55:21 +0200 Subject: [PATCH 3/4] mesh-delivery: cut a walk's phases at the delivery's own merge, never a negative time; moments out of order are unreliable, not a number (hq issue 382) --- .../mesh-delivery/cmd/mesh-delivery/times.go | 73 +++++++++++++++---- .../cmd/mesh-delivery/times_test.go | 49 +++++++++++++ 2 files changed, 107 insertions(+), 15 deletions(-) diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times.go b/modules/mesh-delivery/cmd/mesh-delivery/times.go index b65172a3..4a122087 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times.go @@ -72,9 +72,21 @@ type DeliveryTime struct { UnknownMS int64 `json:"unknown_ms,omitempty"` Phases []WalkPhase `json:"phases"` Silent []string `json:"silent,omitempty"` + // Unreliable says why its moments cannot be trusted (out of order, or its merge after its walk's end): its + // time is then no number — TookMS zero, never counted, said among the unknown by `times`. + Unreliable string `json:"unreliable,omitempty"` } // timeOf is a delivery's time from its walk's phases; nil while the walk's end is not known. +// +// The walk's phases run back to back from its earliest merge to its end: each phase with an end covers the span +// from the end before it, measured or unknown. This delivery's time runs from its own merge, so every span is cut +// there: a phase that ended before its merge is said none ("before its merge"), the phase its merge falls in +// starts at its merge, and an unknown span counts only after it. A merge before the walk's earliest adds that wait +// as unknown time. The measured phases and the unknown time then add up to the delivery time exactly. +// +// Moments out of order (a phase ending before the one before it, or the delivery's merge after the walk's end) +// are a clock or a record that cannot be trusted: the time is kept as unreliable, with why, and no number is said. func timeOf(d *Delivery, w Walk) *DeliveryTime { p := w.Phases if p == nil || p.End == nil || p.From == nil { @@ -90,25 +102,52 @@ func timeOf(d *Delivery, w Walk) *DeliveryTime { 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 { + t := &DeliveryTime{Walk: w.ID, Class: p.Class, From: from, End: *p.End, Silent: p.Silent} + unreliable := func(why string) *DeliveryTime { + t.Unreliable, t.Phases = why, slices.Clone(p.Phases) + return t + } + if from.After(*p.End) { + return unreliable(fmt.Sprintf("its merge (%s) is after its walk's end (%s)", from.UTC().Format(time.RFC3339), + p.End.UTC().Format(time.RFC3339))) + } + var unknown int64 + if from.Before(*p.From) { + unknown += p.From.Sub(from).Milliseconds() // merged before the walk's earliest merge: waited, unmeasured + } + prev := *p.From + for _, ph := range p.Phases { if ph.End == nil { + t.Phases = append(t.Phases, ph) continue } - if ph.State == phaseMeasured && ph.Start != nil && ph.Start.Equal(*p.From) { - 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() + end := *ph.End + if end.Before(prev) { + return unreliable(fmt.Sprintf("its walk's %s ends before the phase before it: its moments are out of order", ph.Name)) } - break + start := prev + prev = end + if end.Before(from) { + ph.State, ph.Start, ph.TookMS, ph.Took, ph.Said = "none", nil, 0, "", "before its merge" + t.Phases = append(t.Phases, ph) + continue + } + if start.Before(from) { + start = from + } + span := end.Sub(start) + if ph.State == phaseMeasured { + s := start + ph.Start, ph.TookMS, ph.Took = &s, span.Milliseconds(), span.Round(100*time.Millisecond).String() + } else { + unknown += span.Milliseconds() + } + t.Phases = append(t.Phases, ph) } + if !prev.Equal(*p.End) { + return unreliable("its walk's phases do not reach its end") + } + t.UnknownMS = unknown took := t.End.Sub(from) t.TookMS, t.Took = took.Milliseconds(), took.Round(time.Second).String() if b, ok := budgets[t.Class]; ok { @@ -151,7 +190,7 @@ func (h *Holder) timeWalk(w Walk) { 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 && + if t == nil || (d.Time != nil && d.Time.TookMS == t.TookMS && d.Time.Unreliable == t.Unreliable && 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 } @@ -250,6 +289,10 @@ func (h *Holder) times(days int) TimesAnswer { if d.Time.End.Before(since) { continue } + if d.Time.Unreliable != "" { + a.Unknown = append(a.Unknown, d.ID+": its time is unreliable: "+d.Time.Unreliable) + continue + } if _, ok := budgets[d.Time.Class]; !ok { a.Unknown = append(a.Unknown, fmt.Sprintf("%s: took %s, its class %q has no budget", d.ID, d.Time.Took, d.Time.Class)) continue diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go index 98f08a6f..857d879f 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go @@ -91,6 +91,35 @@ func TestADeliveryKeepsItsTimeFromItsOwnMerge(t *testing.T) { if dt.UnknownMS != 80000 || dt.TookMS != 110000 { t.Fatalf("unknown first phase: %+v", dt) } + // Merged after the walk's first phase ended (a later merge carried by the walk, its window already running): that + // phase is before its merge, the next starts at its merge, and nothing is negative. + p = phasesOf("leaf", from, ph{"window", 30 * time.Second}, ph{"queued", 60 * time.Second}, ph{"build", 30 * time.Second}) + p.Phases[0].State, p.Phases[0].Start, p.Phases[0].TookMS = phaseUnknown, nil, 0 + dt = timeOf(&Delivery{MergedAt: from.Add(45 * time.Second)}, Walk{ID: "w", Phases: p}) + if dt.Unreliable != "" || dt.UnknownMS != 0 || dt.TookMS != 75000 || dt.Phases[0].State != "none" || + dt.Phases[1].TookMS != 45000 || dt.Phases[2].TookMS != 30000 { + t.Fatalf("merged inside the second phase: %+v", dt) + } + assertSums(t, dt) + // Merged before the walk's earliest merge: the wait is unknown time, and the sum holds. + dt = timeOf(&Delivery{MergedAt: from.Add(-20 * time.Second)}, Walk{ID: "w", Phases: p}) + if dt.UnknownMS != 50000 || dt.TookMS != 140000 { + t.Fatalf("merged before the walk's first merge: %+v", dt) + } + assertSums(t, dt) + // Moments out of order: unreliable, and no number. + bad := phasesOf("leaf", from, ph{"window", 30 * time.Second}, ph{"build", 30 * time.Second}) + early := from.Add(10 * time.Second) + bad.Phases[1].End = &early + bad.End = &early + dt = timeOf(&Delivery{MergedAt: from}, Walk{ID: "w", Phases: bad}) + if dt.Unreliable == "" || dt.TookMS != 0 { + t.Fatalf("out of order is unreliable, with no time: %+v", dt) + } + // Merged after the walk's end: unreliable. + if dt := timeOf(&Delivery{MergedAt: from.Add(time.Hour)}, Walk{ID: "w", Phases: p}); dt.Unreliable == "" || dt.TookMS != 0 { + t.Fatalf("merged after its walk's end: %+v", dt) + } // Exactly its budget is within it. p = phasesOf("leaf", from, ph{"build", 5*time.Minute + 10*time.Second}) if dt := timeOf(&Delivery{MergedAt: from.Add(10 * time.Second)}, Walk{ID: "w", Phases: p}); dt.Over || dt.TookMS != 300000 { @@ -168,3 +197,23 @@ func TestTimesSaysEachClassAgainstItsBudget(t *testing.T) { } func mustString(v any) string { return string(mustJSON(v)) } + +// assertSums checks a delivery time's measured phases and unknown time add up to it, and none is negative. +func assertSums(t *testing.T, dt *DeliveryTime) { + t.Helper() + sum := dt.UnknownMS + if dt.UnknownMS < 0 { + t.Fatalf("negative unknown time: %+v", dt) + } + for _, p := range dt.Phases { + if p.TookMS < 0 { + t.Fatalf("negative phase %s: %+v", p.Name, p) + } + if p.State == phaseMeasured { + sum += p.TookMS + } + } + if sum != dt.TookMS { + t.Fatalf("the phases add up to %dms, the delivery time is %dms: %+v", sum, dt.TookMS, dt) + } +} From 08dab94bb020869115a1ad77e9f0658aa52304bf Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 20:56:50 +0200 Subject: [PATCH 4/4] mesh-delivery: an unreliable time names its phases with no number; tests that it is never counted and that phases short of the walk's end are unreliable --- .../mesh-delivery/cmd/mesh-delivery/times.go | 7 +++- .../cmd/mesh-delivery/times_test.go | 38 +++++++++++++++++++ 2 files changed, 43 insertions(+), 2 deletions(-) diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times.go b/modules/mesh-delivery/cmd/mesh-delivery/times.go index 4a122087..8a6979cc 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times.go @@ -2,7 +2,6 @@ package main import ( "fmt" - "slices" "sort" "strings" "time" @@ -104,7 +103,11 @@ func timeOf(d *Delivery, w Walk) *DeliveryTime { from = from.Truncate(time.Millisecond) t := &DeliveryTime{Walk: w.ID, Class: p.Class, From: from, End: *p.End, Silent: p.Silent} unreliable := func(why string) *DeliveryTime { - t.Unreliable, t.Phases = why, slices.Clone(p.Phases) + // Its phases are named, never timed: a moment out of order makes every number in them suspect. + t.Unreliable, t.Phases = why, nil + for _, ph := range p.Phases { + t.Phases = append(t.Phases, WalkPhase{Name: ph.Name, Tier: ph.Tier, State: phaseUnknown, Said: "unreliable"}) + } return t } if from.After(*p.End) { diff --git a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go index 857d879f..12c9cbd2 100644 --- a/modules/mesh-delivery/cmd/mesh-delivery/times_test.go +++ b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go @@ -116,6 +116,18 @@ func TestADeliveryKeepsItsTimeFromItsOwnMerge(t *testing.T) { if dt.Unreliable == "" || dt.TookMS != 0 { t.Fatalf("out of order is unreliable, with no time: %+v", dt) } + for _, ph := range dt.Phases { + if ph.TookMS != 0 || ph.Start != nil || ph.State != phaseUnknown { + t.Fatalf("an unreliable time says no phase's time: %+v", ph) + } + } + // The walk's phases not reaching its end: unreliable. + short := phasesOf("leaf", from, ph{"window", 30 * time.Second}) + later := from.Add(time.Minute) + short.End = &later + if dt := timeOf(&Delivery{MergedAt: from}, Walk{ID: "w", Phases: short}); dt.Unreliable == "" || dt.TookMS != 0 { + t.Fatalf("phases short of the walk's end: %+v", dt) + } // Merged after the walk's end: unreliable. if dt := timeOf(&Delivery{MergedAt: from.Add(time.Hour)}, Walk{ID: "w", Phases: p}); dt.Unreliable == "" || dt.TookMS != 0 { t.Fatalf("merged after its walk's end: %+v", dt) @@ -217,3 +229,29 @@ func assertSums(t *testing.T, dt *DeliveryTime) { t.Fatalf("the phases add up to %dms, the delivery time is %dms: %+v", sum, dt.TookMS, dt) } } + +// An unreliable time is said among the unknown, never in a median, an over count or the newest of its class. +func TestAnUnreliableTimeIsNeverCounted(t *testing.T) { + w := newWorld(t) + good := walkedOnce(w, 11, "headgood", "mergegood1", phasesOf("leaf", t0, ph{"build", 2 * time.Minute})) + bad := phasesOf("leaf", t0.Add(time.Hour), ph{"window", 30 * time.Second}, ph{"build", 9 * time.Minute}) + early := t0.Add(time.Hour + 10*time.Second) + bad.Phases[1].End, bad.End = &early, &early + unreliable := walkedOnce(w, 12, "headbad", "mergebad01", bad) + if d := w.delivery(unreliable); d.Time == nil || d.Time.Unreliable == "" { + t.Fatalf("the out-of-order walk gave a time: %+v", d.Time) + } + w.later(2 * time.Hour) + a := w.h.times(7) + l := a.Classes[0] + if l.Count != 1 || l.Over != 0 || l.Latest == nil || l.Latest.ID != good || l.WorstID != good { + t.Fatalf("an unreliable time was counted: %+v", l) + } + found := false + for _, u := range a.Unknown { + found = found || strings.HasPrefix(u, unreliable+": its time is unreliable") + } + if !found { + t.Fatalf("the unreliable delivery is not said among the unknown: %v", a.Unknown) + } +}