diff --git a/config/observability-rules.yaml b/config/observability-rules.yaml index c14de1f..09e10a5 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 b3564e1..2376a1f 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 f43cc06..d09a962 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 81c2244..0593191 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 65cbe44..bc55bc4 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)) } }