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)

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

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)
+	}
+}