Emit metrics on execution time of BBR plugins

Add plugin processing latency histogram (bbr_plugin_duration_seconds)
mirroring the EPP pattern. Instrument executePlugins() to record
per-plugin execution time with extension_point, plugin_type, and
plugin_name labels.

Fixes #2355

Signed-off-by: asaadbalum <asaad.balum@gmail.com>

Author: asaadbalum

pkg/bbr/handlers/request.go

@@ -21,6 +21,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"time"
 
 	basepb "github.com/envoyproxy/go-control-plane/envoy/config/core/v3"
 	eppb "github.com/envoyproxy/go-control-plane/envoy/service/ext_proc/v3"
@@ -35,6 +36,8 @@ import (
 const (
 	modelHeader     = "X-Gateway-Model-Name"
 	baseModelHeader = "X-Gateway-Base-Model-Name"
+
+	executeExtensionPoint = "Execute"
 )
 
 // HandleRequestBody handles request bodies.
@@ -161,7 +164,9 @@ func (s *Server) executePlugins(ctx context.Context, headers map[string]string,
 	var err error
 	for _, plugin := range plugins {
 		log.FromContext(ctx).Info("Executing request plugin", "plugin", plugin.TypedName())
+		before := time.Now()
 		updatedHeaders, updatedBody, err = plugin.Execute(ctx, updatedHeaders, updatedBody)
+		metrics.RecordPluginProcessingLatency(executeExtensionPoint, plugin.TypedName().Type, plugin.TypedName().Name, time.Since(before))
 		if err != nil {
 			return fmt.Errorf("failed to execute payload processor %s - %w", plugin.TypedName(), err)
 		}

pkg/bbr/handlers/request_test.go

@@ -31,6 +31,7 @@ import (
 
 	"sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/framework"
 	"sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/metrics"
+	bbrplugins "sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/plugins"
 	logutil "sigs.k8s.io/gateway-api-inference-extension/pkg/common/observability/logging"
 )
 
@@ -301,6 +302,52 @@ func TestHandleRequestBody(t *testing.T) {
 	}
 }
 
+func TestHandleRequestBodyWithPluginMetrics(t *testing.T) {
+	metrics.Register()
+	ctx := logutil.NewTestLoggerIntoContext(context.Background())
+
+	noopPlugin := bbrplugins.NewDefaultPlugin()
+	server := NewServer(false, &fakeDatastore{}, []framework.PayloadProcessor{noopPlugin})
+
+	bodyBytes, _ := json.Marshal(map[string]any{
+		"model":  "bar",
+		"prompt": "test",
+	})
+	_, err := server.HandleRequestBody(ctx, bodyBytes)
+	if err != nil {
+		t.Fatalf("HandleRequestBody returned unexpected error: %v", err)
+	}
+
+	mfs, err := crmetrics.Registry.Gather()
+	if err != nil {
+		t.Fatalf("Failed to gather metrics: %v", err)
+	}
+
+	found := false
+	for _, mf := range mfs {
+		if mf.GetName() == "bbr_plugin_duration_seconds" {
+			for _, m := range mf.GetMetric() {
+				labels := map[string]string{}
+				for _, lp := range m.GetLabel() {
+					labels[lp.GetName()] = lp.GetValue()
+				}
+				if labels["extension_point"] == "Execute" &&
+					labels["plugin_type"] == bbrplugins.DefaultPluginType &&
+					labels["plugin_name"] == bbrplugins.DefaultPluginType {
+					if m.GetHistogram().GetSampleCount() > 0 {
+						found = true
+					}
+				}
+			}
+		}
+	}
+
+	if !found {
+		t.Error("Expected bbr_plugin_duration_seconds metric with extension_point=Execute, " +
+			"plugin_type=no-op-plugin, plugin_name=no-op-plugin to have observations, but none found")
+	}
+}
+
 func mapToBytes(t *testing.T, m map[string]any) []byte {
 	// Convert map to JSON byte array
 	bytes, err := json.Marshal(m)

pkg/bbr/metrics/metrics.go

@@ -18,6 +18,7 @@ package metrics
 
 import (
 	"sync"
+	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
 	compbasemetrics "k8s.io/component-base/metrics"
@@ -54,6 +55,18 @@ var (
 		[]string{},
 	)
 
+	pluginProcessingLatencies = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Subsystem: component,
+			Name:      "plugin_duration_seconds",
+			Help:      metricsutil.HelpMsgWithStability("Plugin processing latency distribution in seconds for each extension point, plugin type and plugin name.", compbasemetrics.ALPHA),
+			Buckets: []float64{
+				0.0001, 0.0002, 0.0005, 0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1,
+			},
+		},
+		[]string{"extension_point", "plugin_type", "plugin_name"},
+	)
+
 	// TODO: Uncomment and use this metrics once the core server implementation has handling to skip body parsing if header exists.
 	/*
 		modelAlreadyPresentInHeaderCounter = prometheus.NewCounterVec(
@@ -75,6 +88,7 @@ func Register() {
 		metrics.Registry.MustRegister(successCounter)
 		metrics.Registry.MustRegister(modelNotInBodyCounter)
 		metrics.Registry.MustRegister(modelNotParsedCounter)
+		metrics.Registry.MustRegister(pluginProcessingLatencies)
 		// metrics.Registry.MustRegister(modelAlreadyPresentInHeaderCounter)
 	})
 }
@@ -94,6 +108,11 @@ func RecordModelNotParsedCounter() {
 	modelNotParsedCounter.WithLabelValues().Inc()
 }
 
+// RecordPluginProcessingLatency records the processing latency for a BBR plugin.
+func RecordPluginProcessingLatency(extensionPoint, pluginType, pluginName string, duration time.Duration) {
+	pluginProcessingLatencies.WithLabelValues(extensionPoint, pluginType, pluginName).Observe(duration.Seconds())
+}
+
 /*
 // RecordModelAlreadyInHeaderCounter records the number of times the model was already found in the request headers.
 func RecordModelAlreadyInHeaderCounter() {

pkg/bbr/metrics/metrics_test.go

@@ -0,0 +1,80 @@
+/*
+Copyright 2026 The Kubernetes Authors.
+
+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 (
+	"os"
+	"testing"
+	"time"
+
+	"k8s.io/component-base/metrics/testutil"
+	crmetrics "sigs.k8s.io/controller-runtime/pkg/metrics"
+)
+
+func TestPluginProcessingLatency(t *testing.T) {
+	Register()
+
+	type pluginLatency struct {
+		extensionPoint string
+		pluginType     string
+		pluginName     string
+		duration       time.Duration
+	}
+
+	scenarios := []struct {
+		name      string
+		latencies []pluginLatency
+	}{
+		{
+			name: "multiple plugins",
+			latencies: []pluginLatency{
+				{
+					extensionPoint: "Execute",
+					pluginType:     "TestPluginA",
+					pluginName:     "PluginA",
+					duration:       5 * time.Millisecond,
+				},
+				{
+					extensionPoint: "Execute",
+					pluginType:     "TestPluginB",
+					pluginName:     "PluginB",
+					duration:       10 * time.Microsecond,
+				},
+			},
+		},
+	}
+	for _, scenario := range scenarios {
+		t.Run(scenario.name, func(t *testing.T) {
+			for _, latency := range scenario.latencies {
+				RecordPluginProcessingLatency(latency.extensionPoint, latency.pluginType, latency.pluginName, latency.duration)
+			}
+
+			wantPluginLatencies, err := os.Open("testdata/plugin_processing_latencies_metric")
+			defer func() {
+				if err := wantPluginLatencies.Close(); err != nil {
+					t.Error(err)
+				}
+			}()
+			if err != nil {
+				t.Fatal(err)
+			}
+			if err := testutil.GatherAndCompare(crmetrics.Registry, wantPluginLatencies, "bbr_plugin_duration_seconds"); err != nil {
+				t.Error(err)
+			}
+		})
+	}
+}

pkg/bbr/metrics/testdata/plugin_processing_latencies_metric

@@ -0,0 +1,28 @@
+# HELP bbr_plugin_duration_seconds [ALPHA] Plugin processing latency distribution in seconds for each extension point, plugin type and plugin name.
+# TYPE bbr_plugin_duration_seconds histogram
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0001"} 0
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0002"} 0
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0005"} 0
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.001"} 0
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.002"} 0
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.005"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.01"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.02"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.05"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="0.1"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA",le="+Inf"} 1
+bbr_plugin_duration_seconds_sum{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA"} 0.005
+bbr_plugin_duration_seconds_count{extension_point="Execute",plugin_name="PluginA",plugin_type="TestPluginA"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0001"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0002"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0005"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.001"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.002"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.005"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.01"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.02"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.05"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="0.1"} 1
+bbr_plugin_duration_seconds_bucket{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB",le="+Inf"} 1
+bbr_plugin_duration_seconds_sum{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB"} 1e-05
+bbr_plugin_duration_seconds_count{extension_point="Execute",plugin_name="PluginB",plugin_type="TestPluginB"} 1