From 17af531a0f14fae95551b81fcc8391d711d93037 Mon Sep 17 00:00:00 2001 From: rldyourmnd Date: Wed, 2 Sep 2026 21:32:30 +0500 Subject: [PATCH] feat(observer): the fleet measures the wait it is judged by Every wait metric the fleet exported stopped when the provider assigned the intent: gha_fleet_queue_oldest_queued_wait_seconds counts only intents still queued, and the rest of the wait -- assignment, boot, runner registration -- belonged to a different gauge with a different threshold. On 2026-09-02 that gauge peaked at 597 s on three scale sets while GitHub's own job records showed waits up to 906 s, so no rule could see the number the fleet is actually judged by. The observer now closes the measurement: for every intent that entered running within the last fifteen minutes it takes the whole wait, from the immutable first-queued stamp to the moment the runner reported running, and exports the sample count, median, ninetieth percentile and maximum, plus the percentile per scale set. queue_started_wait_slow_burn tickets when that percentile stays above the five-minute objective for ten minutes, and its action points at the two phase rules so the reader knows which half grew. Claude-Session: https://claude.ai/code/session_0128syXKxAGCfJGRDxUUNQXp --- config/observability-rules.yaml | 23 +++++++++ internal/fleetobserve/metrics.go | 9 ++++ internal/fleetobserve/observe.go | 60 +++++++++++++++++++++++ internal/fleetobserve/observe_test.go | 40 +++++++++++++++ internal/observabilityrules/rules_test.go | 4 +- 5 files changed, 134 insertions(+), 2 deletions(-) diff --git a/config/observability-rules.yaml b/config/observability-rules.yaml index c14de1f2..09e10a50 100644 --- a/config/observability-rules.yaml +++ b/config/observability-rules.yaml @@ -613,6 +613,29 @@ rules: # rule's own summary names: "between the two-minute objective and the # five-minute page". Held ten minutes it fires once on a day like that one, # which is what a slow-burn ticket should cost. + # The wait a developer feels, closed: first queued to runner running, over + # the jobs that started in the last fifteen minutes. Every other wait rule + # here reads a gauge that stops when the provider assigns the intent, so on + # 2026-09-02 the queued gauge peaked at 597 s on three scale sets while jobs + # waited up to 906 s. This is the number the fleet is judged by, so it is + # the one that carries the objective: a ticket when the ninetieth percentile + # of completed waits stays above five minutes for ten. + - id: queue_started_wait_slow_burn + severity: ticket + query_language: promql + stream_name: gha_fleet_queue_started_wait_p90_seconds_by_scale_set + expression: max by (scale_set) (gha_fleet_queue_started_wait_p90_seconds_by_scale_set) + operator: ">" + threshold: 300 + evaluation_seconds: 300 + hold_seconds: 600 + destination_ref: fleet_oncall + enabled: true + owner: fleet-operations + runbook: https://github.com/NDDev-OpenNetwork/github-actions/blob/main/docs/runbooks/fleet-alerts.md + summary: Jobs that started recently waited longer than the five-minute objective. + action: Read the queued and assigned phases separately -- queue_wait_slow_burn and lifecycle_assigned_stall name which half of the wait grew -- before adding capacity. + recovery: The ninetieth percentile of completed waits holds under five minutes for the hold window. - id: queue_wait_slow_burn severity: ticket query_language: promql diff --git a/internal/fleetobserve/metrics.go b/internal/fleetobserve/metrics.go index b3564e13..2376a1fe 100644 --- a/internal/fleetobserve/metrics.go +++ b/internal/fleetobserve/metrics.go @@ -169,6 +169,15 @@ func RenderPrometheus(snapshot Snapshot, now time.Time, maxStaleness time.Durati labeledGaugeHeader(&output, "gha_fleet_queue_oldest_queued_wait_seconds_by_scale_set", "Longest wait since GitHub queued a still-queued intent, per configured scale set.") for _, scaleSet := range scaleSets { metric(&output, "gha_fleet_queue_oldest_queued_wait_seconds_by_scale_set", map[string]string{"scale_set": scaleSet}, float64(snapshot.Queue.OldestQueuedWaitSecondsByScaleSet[scaleSet])) + + gauge(&output, "gha_fleet_queue_started_wait_samples", "Jobs whose runner started within the completed-wait window.", float64(snapshot.Queue.StartedWaitSamples)) + gauge(&output, "gha_fleet_queue_started_wait_median_seconds", "Median wait, first queued to runner running, over jobs that started in the window.", float64(snapshot.Queue.StartedWaitMedianSeconds)) + gauge(&output, "gha_fleet_queue_started_wait_p90_seconds", "Ninetieth-percentile wait, first queued to runner running, over jobs that started in the window.", float64(snapshot.Queue.StartedWaitP90Seconds)) + gauge(&output, "gha_fleet_queue_started_wait_max_seconds", "Longest wait, first queued to runner running, over jobs that started in the window.", float64(snapshot.Queue.StartedWaitMaxSeconds)) + labeledGaugeHeader(&output, "gha_fleet_queue_started_wait_p90_seconds_by_scale_set", "Ninetieth-percentile completed wait per scale set.") + for _, scaleSet := range scaleSets { + metric(&output, "gha_fleet_queue_started_wait_p90_seconds_by_scale_set", map[string]string{"scale_set": scaleSet}, float64(snapshot.Queue.StartedWaitP90ByScaleSet[scaleSet])) + } } gauge(&output, "gha_fleet_incus_visible_instances", "Instances visible in the restricted Incus project.", float64(snapshot.Incus.VisibleInstances)) gauge(&output, "gha_fleet_incus_visible_maintenance_instances", "Visible exact image builder or smoke instances; observable maintenance capacity, never GitHub job runners.", float64(snapshot.Incus.VisibleMaintenanceInstances)) diff --git a/internal/fleetobserve/observe.go b/internal/fleetobserve/observe.go index f43cc06f..d09a9624 100644 --- a/internal/fleetobserve/observe.go +++ b/internal/fleetobserve/observe.go @@ -318,6 +318,17 @@ type QueueSummary struct { // can never fire. OldestQueuedWaitSeconds int64 `json:"oldest_queued_wait_seconds"` OldestQueuedWaitSecondsByScaleSet map[string]int64 `json:"oldest_queued_wait_seconds_by_scale_set"` + // StartedWait* is the wait a developer actually felt: from the moment + // GitHub first queued the intent to the moment its runner reported + // running, measured over the intents that started within the last + // completedWaitWindow. Every other wait metric here stops at assignment, + // so no rule could see the second half of the wait -- on 2026-09-02 jobs + // waited up to 906 s while the queued gauge peaked at 597 s. + StartedWaitSamples int `json:"started_wait_samples"` + StartedWaitMedianSeconds int64 `json:"started_wait_median_seconds"` + StartedWaitP90Seconds int64 `json:"started_wait_p90_seconds"` + StartedWaitMaxSeconds int64 `json:"started_wait_max_seconds"` + StartedWaitP90ByScaleSet map[string]int64 `json:"started_wait_p90_seconds_by_scale_set"` // QueuedWithoutFirstStamp is how many waiting intents have no immutable // stamp, so their wait is measured from the rewritten QueueTime and is a // lower bound. Without this a rollout window looks calm for the same reason @@ -802,10 +813,13 @@ func summarizeQueue(snapshot queueintent.Snapshot, platform config.Config, now t TerminalNextExpirySeconds: snapshot.TerminalNextExpirySeconds, ByState: make(map[string]int), OldestStateAgeSeconds: make(map[string]int64), + StartedWaitP90ByScaleSet: make(map[string]int64), ByPriority: make(map[int]int), ByScaleSet: make(map[string]int), OldestQueuedWaitSecondsByScaleSet: make(map[string]int64), } + startedWaits := make([]int64, 0) + startedWaitsByScaleSet := make(map[string][]int64) for scaleSet := range knownScaleSets { summary.ByScaleSet[scaleSet] = 0 summary.OldestQueuedWaitSecondsByScaleSet[scaleSet] = 0 @@ -865,6 +879,16 @@ func summarizeQueue(snapshot queueintent.Snapshot, platform config.Config, now t if age > summary.OldestQueueAgeSeconds { summary.OldestQueueAgeSeconds = age } + if intent.State == queueintent.StateRunning && !intent.StateEnteredAt.IsZero() && + now.Sub(intent.StateEnteredAt) <= completedWaitWindow { + // The whole wait, closed: first queued -> running. Only intents + // that started inside the window count, so the number moves with + // the fleet instead of averaging the day. + if wait := int64(intent.StateEnteredAt.Sub(intent.WaitSince()).Seconds()); wait >= 0 { + startedWaits = append(startedWaits, wait) + startedWaitsByScaleSet[intent.ScaleSetName] = append(startedWaitsByScaleSet[intent.ScaleSetName], wait) + } + } if intent.State == queueintent.StateQueued { // From the immutable first-seen stamp, not QueueTime: reconciliation // moves QueueTime forward on an intent that is still waiting, so a @@ -881,9 +905,45 @@ func summarizeQueue(snapshot queueintent.Snapshot, platform config.Config, now t } } } + summary.StartedWaitSamples = len(startedWaits) + summary.StartedWaitMedianSeconds = quantileSeconds(startedWaits, 0.5) + summary.StartedWaitP90Seconds = quantileSeconds(startedWaits, 0.9) + if len(startedWaits) > 0 { + sort.Slice(startedWaits, func(left, right int) bool { return startedWaits[left] < startedWaits[right] }) + summary.StartedWaitMaxSeconds = startedWaits[len(startedWaits)-1] + } + for scaleSet := range knownScaleSets { + summary.StartedWaitP90ByScaleSet[scaleSet] = quantileSeconds(startedWaitsByScaleSet[scaleSet], 0.9) + } return summary, nil } +// completedWaitWindow bounds how recently an intent must have started running +// for its wait to count. Short enough that the number describes the fleet now, +// long enough that a quiet minute does not empty it. +const completedWaitWindow = 15 * time.Minute + +// quantileSeconds is the linear-interpolated quantile of a sample, and zero +// for an empty one: no jobs started is not a long wait. +func quantileSeconds(values []int64, quantile float64) int64 { + if len(values) == 0 { + return 0 + } + ordered := append([]int64(nil), values...) + sort.Slice(ordered, func(left, right int) bool { return ordered[left] < ordered[right] }) + if len(ordered) == 1 { + return ordered[0] + } + position := float64(len(ordered)-1) * quantile + lower := int(position) + upper := lower + 1 + if upper >= len(ordered) { + return ordered[len(ordered)-1] + } + fraction := position - float64(lower) + return ordered[lower] + int64(float64(ordered[upper]-ordered[lower])*fraction) +} + func validateDiagnosticExport( status diagnosticexport.Status, spool workerdiagnostics.SpoolStats, diff --git a/internal/fleetobserve/observe_test.go b/internal/fleetobserve/observe_test.go index 81c22443..05931913 100644 --- a/internal/fleetobserve/observe_test.go +++ b/internal/fleetobserve/observe_test.go @@ -1074,3 +1074,43 @@ func TestFailedWarmReconcilerMakesQueueHostUnhealthy(t *testing.T) { } } } + +// The fleet must be able to see the wait it is judged by: from the moment +// GitHub queued the job to the moment its runner started. Every other wait +// metric stops when the provider assigns the intent, so on 2026-09-02 the +// queued gauge peaked at 597 s while jobs waited up to 906 s. +func TestCompletedWaitMeasuresQueuedToRunning(t *testing.T) { + now := time.Date(2026, time.September, 2, 12, 0, 0, 0, time.UTC) + intents := []queueintent.Intent{ + {Key: "a", ScaleSetName: "nddev-linux-standard", State: queueintent.StateRunning, + FirstQueuedAt: now.Add(-5 * time.Minute), StateEnteredAt: now.Add(-2 * time.Minute), QueueTime: now.Add(-3 * time.Minute)}, + {Key: "b", ScaleSetName: "nddev-linux-standard", State: queueintent.StateRunning, + FirstQueuedAt: now.Add(-11 * time.Minute), StateEnteredAt: now.Add(-1 * time.Minute), QueueTime: now.Add(-3 * time.Minute)}, + // Started long ago: outside the window, so it does not describe the fleet now. + {Key: "c", ScaleSetName: "nddev-linux-standard", State: queueintent.StateRunning, + FirstQueuedAt: now.Add(-90 * time.Minute), StateEnteredAt: now.Add(-60 * time.Minute), QueueTime: now.Add(-70 * time.Minute)}, + // Still queued: it has no completed wait yet. + {Key: "d", ScaleSetName: "nddev-linux-standard", State: queueintent.StateQueued, + FirstQueuedAt: now.Add(-40 * time.Minute), QueueTime: now.Add(-2 * time.Minute)}, + } + summary, err := summarizeQueue(queueintent.Snapshot{Active: intents}, testPlatform(t), now) + if err != nil { + t.Fatal(err) + } + if summary.StartedWaitSamples != 2 { + t.Fatalf("samples = %d, want the two that started inside the window", summary.StartedWaitSamples) + } + if summary.StartedWaitMaxSeconds != 600 { + t.Fatalf("max = %d, want the ten-minute wait", summary.StartedWaitMaxSeconds) + } + if summary.StartedWaitMedianSeconds != 390 { + t.Fatalf("median = %d, want the midpoint of the 180 s and 600 s waits", summary.StartedWaitMedianSeconds) + } + if summary.StartedWaitP90ByScaleSet["nddev-linux-standard"] == 0 { + t.Fatal("the per-scale-set percentile is empty") + } + // The still-queued intent keeps feeding the open-ended gauge, unchanged. + if summary.OldestQueuedWaitSeconds != 2400 { + t.Fatalf("oldest queued wait = %d, want the forty minutes of the waiting intent", summary.OldestQueuedWaitSeconds) + } +} diff --git a/internal/observabilityrules/rules_test.go b/internal/observabilityrules/rules_test.go index 65cbe44f..bc55bc45 100644 --- a/internal/observabilityrules/rules_test.go +++ b/internal/observabilityrules/rules_test.go @@ -11,8 +11,8 @@ func TestRepositoryBundleIsValid(t *testing.T) { if err != nil { t.Fatal(err) } - if len(bundle.Rules) != 30 { - t.Fatalf("rules = %d, want 30", len(bundle.Rules)) + if len(bundle.Rules) != 31 { + t.Fatalf("rules = %d, want 31", len(bundle.Rules)) } }