From 3e1eeff4d3d9d5cebb6173462ba5fb7bc87d26f5 Mon Sep 17 00:00:00 2001 From: Hongyi Wu Date: Wed, 12 Aug 2026 22:36:59 +0000 Subject: [PATCH] fix: register explicit bucket boundaries for duration histograms Following the OpenCensus to OpenTelemetry metrics migration, duration histogram instruments in Config Sync lacked explicit bucket boundaries. This caused the OpenTelemetry Go SDK to fall back to default millisecond-scale boundaries {0, 5, 10, 25, ...}, which for second-unit metrics resulted in all sub-5-second values falling into the (0, 5] bucket and skewing Prometheus histogram_quantile queries (e.g. static 4.75s). This change: - Configures explicit sub-second bucket boundaries for core duration metrics (APICallDuration, ReconcileDuration, RemediateDuration) and long duration metrics (ParserDuration, ApplyDuration). - Configures explicit bucket boundaries for ResourceGroup ReconcileDuration. - Adds unit tests to verify histogram bucket bounds and sub-second data point placement. Fixes b/545631804 --- pkg/kmetrics/exec.go | 6 +- pkg/kmetrics/metrics.go | 12 +- pkg/kmetrics/metrics_test.go | 86 +++++++++++ pkg/kmetrics/record.go | 2 +- pkg/metrics/metrics.go | 16 ++ pkg/metrics/metrics_test.go | 145 ++++++++++++++++++ .../controllers/metrics/metrics.go | 6 + .../controllers/metrics/metrics_test.go | 70 +++++++++ 8 files changed, 338 insertions(+), 5 deletions(-) create mode 100644 pkg/kmetrics/metrics_test.go create mode 100644 pkg/metrics/metrics_test.go create mode 100644 pkg/resourcegroup/controllers/metrics/metrics_test.go diff --git a/pkg/kmetrics/exec.go b/pkg/kmetrics/exec.go index d85fdf7a00..1e18b1ddf9 100644 --- a/pkg/kmetrics/exec.go +++ b/pkg/kmetrics/exec.go @@ -120,7 +120,7 @@ func runKustomizeBuild(ctx context.Context, sendMetrics bool, inputDir string, c resourceCount, err := kustomizeResourcesGenerated(output) if err == nil && sendMetrics { RecordKustomizeResourceCount(ctx, resourceCount) - RecordKustomizeExecutionTime(ctx, float64(executionTime)) + RecordKustomizeExecutionTime(ctx, float64(executionTime.Milliseconds())) } outputs <- output errors <- kustomizeErr @@ -139,14 +139,14 @@ func runKustomizeBuild(ctx context.Context, sendMetrics bool, inputDir string, c return <-outputs, <-errors } -func runCommand(cmd *exec.Cmd) (int64, string, error) { +func runCommand(cmd *exec.Cmd) (time.Duration, string, error) { var stdout bytes.Buffer var stderr bytes.Buffer cmd.Stdout = &stdout cmd.Stderr = &stderr now := time.Now() err := cmd.Run() - executionTime := time.Since(now).Nanoseconds() + executionTime := time.Since(now) if err != nil { return executionTime, stdout.String(), errors.New(stderr.String()) } diff --git a/pkg/kmetrics/metrics.go b/pkg/kmetrics/metrics.go index 128a93cd28..92c3f2b74f 100644 --- a/pkg/kmetrics/metrics.go +++ b/pkg/kmetrics/metrics.go @@ -67,6 +67,15 @@ var ( KustomizeExecutionTime metric.Float64Histogram ) +var ( + // KustomizeBuildLatencyBounds defines the millisecond bounds for the kustomize + // build latency histogram. These must match the pre-OTel-migration view + // aggregation (view.Distribution(0, 10, 20, ..., 10240)) that the Monarch + // metric descriptor was registered with; changing the bounds or the unit + // causes the exporter to fail with a bucket options mismatch. + KustomizeBuildLatencyBounds = []float64{0, 10, 20, 40, 80, 160, 320, 640, 1280, 2560, 5120, 10240} +) + // InitializeOTelKustomizeMetrics initializes OpenTelemetry Kustomize metrics instruments func InitializeOTelKustomizeMetrics() error { klog.V(5).Infof("METRIC DEBUG: Initializing OpenTelemetry kustomize metrics instruments") @@ -152,8 +161,9 @@ func InitializeOTelKustomizeMetrics() error { // Initialize histogram instrument KustomizeExecutionTime, err = meter.Float64Histogram( "kustomize_build_latency", - metric.WithDescription("Kustomize build latency"), + metric.WithDescription("Kustomize build latency in milliseconds"), metric.WithUnit("ms"), + metric.WithExplicitBucketBoundaries(KustomizeBuildLatencyBounds...), ) if err != nil { klog.V(5).ErrorS(err, "METRIC DEBUG: Failed to create KustomizeExecutionTime histogram") diff --git a/pkg/kmetrics/metrics_test.go b/pkg/kmetrics/metrics_test.go new file mode 100644 index 0000000000..ba0aa06b48 --- /dev/null +++ b/pkg/kmetrics/metrics_test.go @@ -0,0 +1,86 @@ +// Copyright 2026 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package kmetrics + +import ( + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "go.opentelemetry.io/otel" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.opentelemetry.io/otel/sdk/resource" +) + +func TestInitializeOTelKustomizeMetrics_HistogramBuckets(t *testing.T) { + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider( + sdkmetric.WithResource(resource.NewSchemaless()), + sdkmetric.WithReader(reader), + ) + otel.SetMeterProvider(meterProvider) + + if err := InitializeOTelKustomizeMetrics(); err != nil { + t.Fatalf("InitializeOTelKustomizeMetrics() failed: %v", err) + } + + ctx := t.Context() + // Record a 350ms build duration in milliseconds + executionTime := 350 * time.Millisecond + RecordKustomizeExecutionTime(ctx, float64(executionTime.Milliseconds())) + + var rm metricdata.ResourceMetrics + if err := reader.Collect(ctx, &rm); err != nil { + t.Fatalf("reader.Collect() failed: %v", err) + } + + var foundPoint *metricdata.HistogramDataPoint[float64] + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == "kustomize_build_latency" { + if hist, ok := m.Data.(metricdata.Histogram[float64]); ok && len(hist.DataPoints) > 0 { + foundPoint = &hist.DataPoints[0] + } + } + } + } + + if foundPoint == nil { + t.Fatalf("Histogram %q was not found in collected metrics", "kustomize_build_latency") + } + + if diff := cmp.Diff(KustomizeBuildLatencyBounds, foundPoint.Bounds); diff != "" { + t.Errorf("Histogram %q bucket boundaries mismatch (-want +got):\n%s", "kustomize_build_latency", diff) + } + + // For 350ms and KustomizeBuildLatencyBounds [0, 10, 20, 40, 80, 160, 320, 640, ...]: + // Index 7: (320, 640] <-- 350ms must fall in this bucket + if len(foundPoint.BucketCounts) <= 7 { + t.Fatalf("Expected at least 8 bucket counts, got %d", len(foundPoint.BucketCounts)) + } + if foundPoint.BucketCounts[7] != 1 { + t.Errorf("BucketCounts[7] (interval (320, 640]) = %d, want 1. Full BucketCounts: %v", + foundPoint.BucketCounts[7], foundPoint.BucketCounts) + } + + // Verify the overflow (+Inf) bucket is empty. Before the fix, durations were + // recorded in nanoseconds against millisecond-scale default buckets, so every + // recording landed in the overflow bucket. + overflowIdx := len(foundPoint.BucketCounts) - 1 + if foundPoint.BucketCounts[overflowIdx] != 0 { + t.Errorf("BucketCounts[%d] (+Inf overflow bucket) = %d, want 0", overflowIdx, foundPoint.BucketCounts[overflowIdx]) + } +} diff --git a/pkg/kmetrics/record.go b/pkg/kmetrics/record.go index 61bb158688..c5e94a981b 100644 --- a/pkg/kmetrics/record.go +++ b/pkg/kmetrics/record.go @@ -48,7 +48,7 @@ func RecordKustomizeResourceCount(ctx context.Context, resourceCount int) { // RecordKustomizeExecutionTime produces measurement for KustomizeExecutionTime view func RecordKustomizeExecutionTime(ctx context.Context, executionTime float64) { - klog.V(5).Infof("METRIC DEBUG: Recording KustomizeExecutionTime: executionTime=%.3fs", executionTime) + klog.V(5).Infof("METRIC DEBUG: Recording KustomizeExecutionTime: executionTime=%.0fms", executionTime) KustomizeExecutionTime.Record(ctx, executionTime) } diff --git a/pkg/metrics/metrics.go b/pkg/metrics/metrics.go index f31053f7e9..db06440240 100644 --- a/pkg/metrics/metrics.go +++ b/pkg/metrics/metrics.go @@ -51,6 +51,17 @@ const ( InternalErrorsName = "internal_errors_total" ) +var ( + // DistributionBounds defines the bounds for a histogram distribution measuring short durations. + DistributionBounds = []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10} + + // LongDistributionBounds defines the bounds for a histogram distribution measuring long durations. + // These must match the pre-registered Monarch metric descriptor for + // parser_duration_seconds and apply_duration_seconds; changing them causes + // the exporter to fail with a bucket options mismatch. + LongDistributionBounds = []float64{1, 5, 10, 30, 60, 300, 600, 1200, 1800, 3600, 5400} +) + var ( // APICallDuration metric measures the latency of API server calls. APICallDuration metric.Float64Histogram @@ -112,6 +123,7 @@ func InitializeOTelMetrics() error { APICallDurationName, metric.WithDescription("The duration of API server calls in seconds"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(DistributionBounds...), ) if err != nil { klog.V(5).ErrorS(err, "METRIC DEBUG: Failed to create APICallDuration histogram") @@ -123,6 +135,7 @@ func InitializeOTelMetrics() error { ReconcileDurationName, metric.WithDescription("The duration of reconcile events in seconds"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(DistributionBounds...), ) if err != nil { return err @@ -132,6 +145,7 @@ func InitializeOTelMetrics() error { ParserDurationName, metric.WithDescription("The duration of the parse-apply-watch loop in seconds"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(LongDistributionBounds...), ) if err != nil { return err @@ -141,6 +155,7 @@ func InitializeOTelMetrics() error { ApplyDurationName, metric.WithDescription("The duration of applier events in seconds"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(LongDistributionBounds...), ) if err != nil { return err @@ -150,6 +165,7 @@ func InitializeOTelMetrics() error { RemediateDurationName, metric.WithDescription("The duration of remediator reconciliation events"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(DistributionBounds...), ) if err != nil { return err diff --git a/pkg/metrics/metrics_test.go b/pkg/metrics/metrics_test.go new file mode 100644 index 0000000000..a33dfe5d62 --- /dev/null +++ b/pkg/metrics/metrics_test.go @@ -0,0 +1,145 @@ +// Copyright 2026 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package metrics + +import ( + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "go.opentelemetry.io/otel" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.opentelemetry.io/otel/sdk/resource" +) + +func TestInitializeOTelMetrics_HistogramBuckets(t *testing.T) { + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider( + sdkmetric.WithResource(resource.NewSchemaless()), + sdkmetric.WithReader(reader), + ) + otel.SetMeterProvider(meterProvider) + + if err := InitializeOTelMetrics(); err != nil { + t.Fatalf("InitializeOTelMetrics() failed: %v", err) + } + + ctx := t.Context() + startTime := time.Now().Add(-350 * time.Millisecond) + + RecordAPICallDuration(ctx, "get", "success", startTime) + RecordReconcileDuration(ctx, "success", startTime) + RecordParserDuration(ctx, "git", "root", "success", startTime) + RecordApplyDuration(ctx, "success", "abcdef", startTime) + RecordRemediateDuration(ctx, "success", startTime) + + var rm metricdata.ResourceMetrics + if err := reader.Collect(ctx, &rm); err != nil { + t.Fatalf("reader.Collect() failed: %v", err) + } + + expectedHistograms := map[string][]float64{ + APICallDurationName: DistributionBounds, + ReconcileDurationName: DistributionBounds, + ParserDurationName: LongDistributionBounds, + ApplyDurationName: LongDistributionBounds, + RemediateDurationName: DistributionBounds, + } + + foundHistograms := make(map[string][]float64) + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if hist, ok := m.Data.(metricdata.Histogram[float64]); ok { + if len(hist.DataPoints) > 0 { + foundHistograms[m.Name] = hist.DataPoints[0].Bounds + } + } + } + } + + for metricName, wantBounds := range expectedHistograms { + t.Run(metricName, func(t *testing.T) { + gotBounds, ok := foundHistograms[metricName] + if !ok { + t.Fatalf("Histogram %q was not found in collected metrics", metricName) + } + if diff := cmp.Diff(wantBounds, gotBounds); diff != "" { + t.Errorf("Histogram %q bucket boundaries mismatch (-want +got):\n%s", metricName, diff) + } + }) + } +} + +func TestRecordDuration_SubsecondBucketPlacement(t *testing.T) { + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider( + sdkmetric.WithResource(resource.NewSchemaless()), + sdkmetric.WithReader(reader), + ) + otel.SetMeterProvider(meterProvider) + + if err := InitializeOTelMetrics(); err != nil { + t.Fatalf("InitializeOTelMetrics() failed: %v", err) + } + + ctx := t.Context() + // Record an exact 350ms duration (0.35s) + startTime := time.Now().Add(-350 * time.Millisecond) + RecordAPICallDuration(ctx, "get", "success", startTime) + + var rm metricdata.ResourceMetrics + if err := reader.Collect(ctx, &rm); err != nil { + t.Fatalf("reader.Collect() failed: %v", err) + } + + var foundPoint *metricdata.HistogramDataPoint[float64] + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == APICallDurationName { + if hist, ok := m.Data.(metricdata.Histogram[float64]); ok && len(hist.DataPoints) > 0 { + foundPoint = &hist.DataPoints[0] + } + } + } + } + + if foundPoint == nil { + t.Fatalf("Metric %q was not recorded", APICallDurationName) + } + + // For 0.35s and DistributionBounds [.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10]: + // Index 0: <= 0.005 + // Index 1: (0.005, 0.01] + // Index 2: (0.01, 0.025] + // Index 3: (0.025, 0.05] + // Index 4: (0.05, 0.1] + // Index 5: (0.1, 0.25] + // Index 6: (0.25, 0.5] <-- 0.35s must fall in this sub-second bucket + // Index 9: (2.5, 5.0] <-- Before fix, this was where it fell (le=5) + if len(foundPoint.BucketCounts) <= 6 { + t.Fatalf("Expected at least 7 bucket counts, got %d", len(foundPoint.BucketCounts)) + } + + if foundPoint.BucketCounts[6] != 1 { + t.Errorf("BucketCounts[6] (interval (0.25, 0.5]) = %d, want 1. Full BucketCounts: %v", + foundPoint.BucketCounts[6], foundPoint.BucketCounts) + } + + // Verify that the coarse 5-second bucket (index 9) is 0, confirming it didn't fall into the 5s bucket + if foundPoint.BucketCounts[9] != 0 { + t.Errorf("BucketCounts[9] (interval (2.5, 5.0]) = %d, want 0", foundPoint.BucketCounts[9]) + } +} diff --git a/pkg/resourcegroup/controllers/metrics/metrics.go b/pkg/resourcegroup/controllers/metrics/metrics.go index 0f413ba9a3..97615bfc51 100644 --- a/pkg/resourcegroup/controllers/metrics/metrics.go +++ b/pkg/resourcegroup/controllers/metrics/metrics.go @@ -82,6 +82,11 @@ var ( PipelineError metric.Int64Gauge ) +var ( + // RGReconcileDurationBounds defines the bounds for ResourceGroup reconcile duration histogram. + RGReconcileDurationBounds = []float64{0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10} +) + // InitializeOTelResourceGroupMetrics initializes OpenTelemetry Resource Group metrics instruments func InitializeOTelResourceGroupMetrics() error { meter := otel.Meter("config-sync-resourcegroup") @@ -93,6 +98,7 @@ func InitializeOTelResourceGroupMetrics() error { RGReconcileDurationName, metric.WithDescription("Time duration in seconds of reconciling a ResourceGroup CR by the ResourceGroup controller"), metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(RGReconcileDurationBounds...), ) if err != nil { return err diff --git a/pkg/resourcegroup/controllers/metrics/metrics_test.go b/pkg/resourcegroup/controllers/metrics/metrics_test.go new file mode 100644 index 0000000000..ed5dd700d2 --- /dev/null +++ b/pkg/resourcegroup/controllers/metrics/metrics_test.go @@ -0,0 +1,70 @@ +// Copyright 2026 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package metrics + +import ( + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "go.opentelemetry.io/otel" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.opentelemetry.io/otel/sdk/resource" +) + +func TestInitializeOTelResourceGroupMetrics_HistogramBuckets(t *testing.T) { + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider( + sdkmetric.WithResource(resource.NewSchemaless()), + sdkmetric.WithReader(reader), + ) + otel.SetMeterProvider(meterProvider) + + if err := InitializeOTelResourceGroupMetrics(); err != nil { + t.Fatalf("InitializeOTelResourceGroupMetrics() failed: %v", err) + } + + ctx := t.Context() + startTime := time.Now().Add(-200 * time.Millisecond) + + RecordReconcileDuration(ctx, "FinishReconciling", startTime) + + var rm metricdata.ResourceMetrics + if err := reader.Collect(ctx, &rm); err != nil { + t.Fatalf("reader.Collect() failed: %v", err) + } + + var gotBounds []float64 + var found bool + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == RGReconcileDurationName { + if hist, ok := m.Data.(metricdata.Histogram[float64]); ok && len(hist.DataPoints) > 0 { + gotBounds = hist.DataPoints[0].Bounds + found = true + } + } + } + } + + if !found { + t.Fatalf("Histogram %q was not found in collected metrics", RGReconcileDurationName) + } + + if diff := cmp.Diff(RGReconcileDurationBounds, gotBounds); diff != "" { + t.Errorf("Histogram %q bucket boundaries mismatch (-want +got):\n%s", RGReconcileDurationName, diff) + } +}