diff --git a/cmd/ghalistener/metrics/metrics.go b/cmd/ghalistener/metrics/metrics.go index a1bbd472..fd8021ec 100644 --- a/cmd/ghalistener/metrics/metrics.go +++ b/cmd/ghalistener/metrics/metrics.go @@ -485,9 +485,17 @@ func (e *exporter) RecordStatistics(stats *scaleset.RunnerScaleSetStatistic) { } func (e *exporter) RecordJobStarted(msg *scaleset.JobStarted) { + if msg.RunnerAssignTime.IsZero() { + return + } + l := e.startedJobLabels(msg) e.incCounter(MetricStartedJobsTotal, l) + if msg.ScaleSetAssignTime.IsZero() || msg.RunnerAssignTime.Before(msg.ScaleSetAssignTime) { + return + } + startupDuration := msg.RunnerAssignTime.Unix() - msg.ScaleSetAssignTime.Unix() e.observeHistogram(MetricJobStartupDurationSeconds, l, float64(startupDuration)) } @@ -499,7 +507,13 @@ func (e *exporter) RecordJobCompleted(msg *scaleset.JobCompleted) { l := e.completedJobLabels(msg) e.incCounter(MetricCompletedJobsTotal, l) - e.observeHistogram(MetricJobExecutionDurationSeconds, l, float64(msg.FinishTime.Unix()-msg.RunnerAssignTime.Unix())) + + if msg.FinishTime.IsZero() || msg.FinishTime.Before(msg.RunnerAssignTime) { + return + } + + finishDuration := msg.FinishTime.Unix() - msg.RunnerAssignTime.Unix() + e.observeHistogram(MetricJobExecutionDurationSeconds, l, float64(finishDuration)) } func (e *exporter) RecordDesiredRunners(count int) { diff --git a/cmd/ghalistener/metrics/metrics_test.go b/cmd/ghalistener/metrics/metrics_test.go index e62d77e7..8b23d688 100644 --- a/cmd/ghalistener/metrics/metrics_test.go +++ b/cmd/ghalistener/metrics/metrics_test.go @@ -3,9 +3,12 @@ package metrics import ( "log/slog" "testing" + "time" "github.com/actions/actions-runner-controller/apis/actions.github.com/v1alpha1" + "github.com/actions/scaleset" "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -265,3 +268,302 @@ func TestExporterConfigDefaults(t *testing.T) { assert.Equal(t, want, config) } + +func newTestExporter(t *testing.T, metricsConfig v1alpha1.MetricsConfig) (*exporter, *prometheus.Registry) { + t.Helper() + reg := prometheus.NewRegistry() + m := installMetrics(metricsConfig, reg, discardLogger) + e := &exporter{ + scaleSetLabels: prometheus.Labels{ + labelKeyEnterprise: "test-enterprise", + labelKeyOrganization: "test-org", + labelKeyRepository: "test-repo", + labelKeyRunnerScaleSetName: "test-scale-set", + labelKeyRunnerScaleSetNamespace: "test-namespace", + }, + metrics: m, + } + return e, reg +} + +func gatherMetrics(t *testing.T, reg *prometheus.Registry) map[string]*dto.MetricFamily { + t.Helper() + mfs, err := reg.Gather() + require.NoError(t, err) + result := make(map[string]*dto.MetricFamily, len(mfs)) + for _, mf := range mfs { + result[mf.GetName()] = mf + } + return result +} + +func counterValue(t *testing.T, metrics map[string]*dto.MetricFamily, name string) float64 { + t.Helper() + mf, ok := metrics[name] + if !ok || len(mf.GetMetric()) == 0 { + return 0 + } + return mf.GetMetric()[0].GetCounter().GetValue() +} + +func histogramSampleCount(t *testing.T, metrics map[string]*dto.MetricFamily, name string) uint64 { + t.Helper() + mf, ok := metrics[name] + if !ok || len(mf.GetMetric()) == 0 { + return 0 + } + return mf.GetMetric()[0].GetHistogram().GetSampleCount() +} + +func histogramSampleSum(t *testing.T, metrics map[string]*dto.MetricFamily, name string) float64 { + t.Helper() + mf, ok := metrics[name] + if !ok || len(mf.GetMetric()) == 0 { + return 0 + } + return mf.GetMetric()[0].GetHistogram().GetSampleSum() +} + +func TestRecordJobStarted(t *testing.T) { + startedMetrics := v1alpha1.MetricsConfig{ + Counters: map[string]*v1alpha1.CounterMetric{ + MetricStartedJobsTotal: { + Labels: []string{ + labelKeyEnterprise, labelKeyOrganization, labelKeyRepository, + labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName, + labelKeyJobWorkflowTarget, labelKeyEventName, + }, + }, + }, + Histograms: map[string]*v1alpha1.HistogramMetric{ + MetricJobStartupDurationSeconds: { + Labels: []string{ + labelKeyEnterprise, labelKeyOrganization, labelKeyRepository, + labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName, + labelKeyJobWorkflowTarget, labelKeyEventName, + }, + }, + }, + } + + now := time.Now() + + tests := []struct { + name string + msg scaleset.JobStarted + wantCounterValue float64 + wantSampleCount uint64 + wantSampleSum float64 + }{ + { + name: "zero RunnerAssignTime and ScaleSetAssignTime", + msg: scaleset.JobStarted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: time.Time{}, + ScaleSetAssignTime: time.Time{}, + }, + }, + wantCounterValue: 0, + wantSampleCount: 0, + }, + { + name: "zero RunnerAssignTime", + msg: scaleset.JobStarted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: time.Time{}, + ScaleSetAssignTime: now, + }, + }, + wantCounterValue: 0, + wantSampleCount: 0, + }, + { + name: "zero ScaleSetAssignTime still counts the started job but skips the duration", + msg: scaleset.JobStarted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: now, + ScaleSetAssignTime: time.Time{}, + }, + }, + wantCounterValue: 1, + wantSampleCount: 0, + }, + { + name: "RunnerAssignTime before ScaleSetAssignTime still counts the started job but skips the duration", + msg: scaleset.JobStarted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: now, + ScaleSetAssignTime: now.Add(10 * time.Second), + }, + }, + wantCounterValue: 1, + wantSampleCount: 0, + }, + { + name: "valid timestamps", + msg: scaleset.JobStarted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + ScaleSetAssignTime: now, + RunnerAssignTime: now.Add(10 * time.Second), + }, + }, + wantCounterValue: 1, + wantSampleCount: 1, + wantSampleSum: 10, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + e, reg := newTestExporter(t, startedMetrics) + e.RecordJobStarted(&tt.msg) + metrics := gatherMetrics(t, reg) + assert.Equal(t, tt.wantCounterValue, counterValue(t, metrics, MetricStartedJobsTotal)) + assert.Equal(t, tt.wantSampleCount, histogramSampleCount(t, metrics, MetricJobStartupDurationSeconds)) + assert.Equal(t, tt.wantSampleSum, histogramSampleSum(t, metrics, MetricJobStartupDurationSeconds)) + }) + } +} + +func TestRecordJobCompleted(t *testing.T) { + completedMetrics := v1alpha1.MetricsConfig{ + Counters: map[string]*v1alpha1.CounterMetric{ + MetricCompletedJobsTotal: { + Labels: []string{ + labelKeyEnterprise, labelKeyOrganization, labelKeyRepository, + labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName, + labelKeyJobWorkflowTarget, labelKeyEventName, labelKeyJobResult, + }, + }, + }, + Histograms: map[string]*v1alpha1.HistogramMetric{ + MetricJobExecutionDurationSeconds: { + Labels: []string{ + labelKeyEnterprise, labelKeyOrganization, labelKeyRepository, + labelKeyJobName, labelKeyJobWorkflowRef, labelKeyJobWorkflowName, + labelKeyJobWorkflowTarget, labelKeyEventName, labelKeyJobResult, + }, + }, + }, + } + + now := time.Now() + + tests := []struct { + name string + msg scaleset.JobCompleted + wantCounterValue float64 + wantSampleCount uint64 + wantSampleSum float64 + }{ + { + name: "zero RunnerAssignTime", + msg: scaleset.JobCompleted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: time.Time{}, + FinishTime: now, + }, + Result: "success", + }, + wantCounterValue: 0, + wantSampleCount: 0, + }, + { + name: "zero FinishTime still counts the completed job but skips the duration", + msg: scaleset.JobCompleted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: now, + FinishTime: time.Time{}, + }, + Result: "success", + }, + wantCounterValue: 1, + wantSampleCount: 0, + }, + { + name: "FinishTime before RunnerAssignTime still counts the completed job but skips the duration", + msg: scaleset.JobCompleted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + RunnerAssignTime: now.Add(20 * time.Second), + FinishTime: now, + }, + Result: "success", + }, + wantCounterValue: 1, + wantSampleCount: 0, + }, + { + name: "valid timestamps", + msg: scaleset.JobCompleted{ + JobMessageBase: scaleset.JobMessageBase{ + OwnerName: "myorg", + RepositoryName: "myrepo", + JobDisplayName: "build", + JobWorkflowRef: "myorg/myrepo/.github/workflows/build.yml@refs/heads/main", + EventName: "push", + // ScaleSetAssignTime represents queue-wait time and must not + // leak into the execution duration, which should only measure + // FinishTime - RunnerAssignTime. + ScaleSetAssignTime: now.Add(-1 * time.Minute), + RunnerAssignTime: now, + FinishTime: now.Add(10 * time.Second), + }, + Result: "success", + }, + wantCounterValue: 1, + wantSampleCount: 1, + wantSampleSum: 10, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + e, reg := newTestExporter(t, completedMetrics) + e.RecordJobCompleted(&tt.msg) + metrics := gatherMetrics(t, reg) + assert.Equal(t, tt.wantCounterValue, counterValue(t, metrics, MetricCompletedJobsTotal)) + assert.Equal(t, tt.wantSampleCount, histogramSampleCount(t, metrics, MetricJobExecutionDurationSeconds)) + assert.Equal(t, tt.wantSampleSum, histogramSampleSum(t, metrics, MetricJobExecutionDurationSeconds)) + }) + } +}