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..8a6979cc --- /dev/null +++ b/modules/mesh-delivery/cmd/mesh-delivery/times.go @@ -0,0 +1,373 @@ +package main + +import ( + "fmt" + "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"` + // 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 { + 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, Silent: p.Silent} + unreliable := func(why string) *DeliveryTime { + // 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) { + 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 + } + 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)) + } + 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 { + 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 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 + } + 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.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 + } + 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 + } + 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 + } + 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..12c9cbd2 --- /dev/null +++ b/modules/mesh-delivery/cmd/mesh-delivery/times_test.go @@ -0,0 +1,257 @@ +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) + } + // 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) + } + // 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) + } + 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) + } + // 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() + 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)) } + +// 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) + } +} + +// 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) + } +} 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",