From 662c4105d3673b5cfec260db83f57891664cc83b Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 20:55:21 +0200 Subject: [PATCH] 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) + } +}