Skip to content

Commit 3830d80

Browse files
asaadbalumkaushikmitr
asaadbalum
authored and
kaushikmitr
committed
Emit metrics on execution time of BBR plugins (kubernetes-sigs#2379)
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. Signed-off-by: asaadbalum <asaad.balum@gmail.com>
1 parent a9d5580 commit 3830d80

5 files changed

Lines changed: 179 additions & 0 deletions

File tree

‎pkg/bbr/handlers/request.go‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ import (
2121
"encoding/json"
2222
"errors"
2323
"fmt"
24+
"time"
2425

2526
basepb "github.com/envoyproxy/go-control-plane/envoy/config/core/v3"
2627
eppb "github.com/envoyproxy/go-control-plane/envoy/service/ext_proc/v3"
@@ -35,6 +36,8 @@ import (
3536
const (
3637
modelHeader = "X-Gateway-Model-Name"
3738
baseModelHeader = "X-Gateway-Base-Model-Name"
39+
40+
executeExtensionPoint = "Request"
3841
)
3942

4043
// HandleRequestBody handles request bodies.
@@ -161,7 +164,9 @@ func (s *Server) executePlugins(ctx context.Context, headers map[string]string,
161164
var err error
162165
for _, plugin := range plugins {
163166
log.FromContext(ctx).Info("Executing request plugin", "plugin", plugin.TypedName())
167+
before := time.Now()
164168
updatedHeaders, updatedBody, err = plugin.Execute(ctx, updatedHeaders, updatedBody)
169+
metrics.RecordPluginProcessingLatency(executeExtensionPoint, plugin.TypedName().Type, plugin.TypedName().Name, time.Since(before))
165170
if err != nil {
166171
return fmt.Errorf("failed to execute payload processor %s - %w", plugin.TypedName(), err)
167172
}

‎pkg/bbr/handlers/request_test.go‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ import (
3131

3232
"sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/framework"
3333
"sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/metrics"
34+
"sigs.k8s.io/gateway-api-inference-extension/pkg/bbr/plugins"
3435
logutil "sigs.k8s.io/gateway-api-inference-extension/pkg/common/observability/logging"
3536
)
3637

@@ -301,6 +302,52 @@ func TestHandleRequestBody(t *testing.T) {
301302
}
302303
}
303304

305+
func TestHandleRequestBodyWithPluginMetrics(t *testing.T) {
306+
metrics.Register()
307+
ctx := logutil.NewTestLoggerIntoContext(context.Background())
308+
309+
noopPlugin := plugins.NewDefaultPlugin()
310+
server := NewServer(false, &fakeDatastore{}, []framework.PayloadProcessor{noopPlugin})
311+
312+
bodyBytes, _ := json.Marshal(map[string]any{
313+
"model": "bar",
314+
"prompt": "test",
315+
})
316+
_, err := server.HandleRequestBody(ctx, bodyBytes)
317+
if err != nil {
318+
t.Fatalf("HandleRequestBody returned unexpected error: %v", err)
319+
}
320+
321+
mfs, err := crmetrics.Registry.Gather()
322+
if err != nil {
323+
t.Fatalf("Failed to gather metrics: %v", err)
324+
}
325+
326+
found := false
327+
for _, mf := range mfs {
328+
if mf.GetName() == "bbr_plugin_duration_seconds" {
329+
for _, m := range mf.GetMetric() {
330+
labels := map[string]string{}
331+
for _, lp := range m.GetLabel() {
332+
labels[lp.GetName()] = lp.GetValue()
333+
}
334+
if labels["extension_point"] == "Request" &&
335+
labels["plugin_type"] == plugins.DefaultPluginType &&
336+
labels["plugin_name"] == plugins.DefaultPluginType {
337+
if m.GetHistogram().GetSampleCount() > 0 {
338+
found = true
339+
}
340+
}
341+
}
342+
}
343+
}
344+
345+
if !found {
346+
t.Error("Expected bbr_plugin_duration_seconds metric with extension_point=Request, " +
347+
"plugin_type=no-op-plugin, plugin_name=no-op-plugin to have observations, but none found")
348+
}
349+
}
350+
304351
func mapToBytes(t *testing.T, m map[string]any) []byte {
305352
// Convert map to JSON byte array
306353
bytes, err := json.Marshal(m)

‎pkg/bbr/metrics/metrics.go‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ package metrics
1818

1919
import (
2020
"sync"
21+
"time"
2122

2223
"github.com/prometheus/client_golang/prometheus"
2324
compbasemetrics "k8s.io/component-base/metrics"
@@ -54,6 +55,18 @@ var (
5455
[]string{},
5556
)
5657

58+
pluginProcessingLatencies = prometheus.NewHistogramVec(
59+
prometheus.HistogramOpts{
60+
Subsystem: component,
61+
Name: "plugin_duration_seconds",
62+
Help: metricsutil.HelpMsgWithStability("Plugin processing latency distribution in seconds for each extension point, plugin type and plugin name.", compbasemetrics.ALPHA),
63+
Buckets: []float64{
64+
0.0001, 0.0002, 0.0005, 0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1,
65+
},
66+
},
67+
[]string{"extension_point", "plugin_type", "plugin_name"},
68+
)
69+
5770
// TODO: Uncomment and use this metrics once the core server implementation has handling to skip body parsing if header exists.
5871
/*
5972
modelAlreadyPresentInHeaderCounter = prometheus.NewCounterVec(
@@ -75,6 +88,7 @@ func Register() {
7588
metrics.Registry.MustRegister(successCounter)
7689
metrics.Registry.MustRegister(modelNotInBodyCounter)
7790
metrics.Registry.MustRegister(modelNotParsedCounter)
91+
metrics.Registry.MustRegister(pluginProcessingLatencies)
7892
// metrics.Registry.MustRegister(modelAlreadyPresentInHeaderCounter)
7993
})
8094
}
@@ -94,6 +108,11 @@ func RecordModelNotParsedCounter() {
94108
modelNotParsedCounter.WithLabelValues().Inc()
95109
}
96110

111+
// RecordPluginProcessingLatency records the processing latency for a BBR plugin.
112+
func RecordPluginProcessingLatency(extensionPoint, pluginType, pluginName string, duration time.Duration) {
113+
pluginProcessingLatencies.WithLabelValues(extensionPoint, pluginType, pluginName).Observe(duration.Seconds())
114+
}
115+
97116
/*
98117
// RecordModelAlreadyInHeaderCounter records the number of times the model was already found in the request headers.
99118
func RecordModelAlreadyInHeaderCounter() {

‎pkg/bbr/metrics/metrics_test.go‎

Lines changed: 80 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,80 @@
1+
/*
2+
Copyright 2026 The Kubernetes Authors.
3+
4+
Licensed under the Apache License, Version 2.0 (the "License");
5+
you may not use this file except in compliance with the License.
6+
You may obtain a copy of the License at
7+
8+
http://www.apache.org/licenses/LICENSE-2.0
9+
10+
Unless required by applicable law or agreed to in writing, software
11+
distributed under the License is distributed on an "AS IS" BASIS,
12+
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
See the License for the specific language governing permissions and
14+
limitations under the License.
15+
*/
16+
17+
package metrics
18+
19+
import (
20+
"os"
21+
"testing"
22+
"time"
23+
24+
"k8s.io/component-base/metrics/testutil"
25+
crmetrics "sigs.k8s.io/controller-runtime/pkg/metrics"
26+
)
27+
28+
func TestPluginProcessingLatency(t *testing.T) {
29+
Register()
30+
31+
type pluginLatency struct {
32+
extensionPoint string
33+
pluginType string
34+
pluginName string
35+
duration time.Duration
36+
}
37+
38+
scenarios := []struct {
39+
name string
40+
latencies []pluginLatency
41+
}{
42+
{
43+
name: "multiple plugins",
44+
latencies: []pluginLatency{
45+
{
46+
extensionPoint: "Request",
47+
pluginType: "TestPluginA",
48+
pluginName: "PluginA",
49+
duration: 5 * time.Millisecond,
50+
},
51+
{
52+
extensionPoint: "Request",
53+
pluginType: "TestPluginB",
54+
pluginName: "PluginB",
55+
duration: 10 * time.Microsecond,
56+
},
57+
},
58+
},
59+
}
60+
for _, scenario := range scenarios {
61+
t.Run(scenario.name, func(t *testing.T) {
62+
for _, latency := range scenario.latencies {
63+
RecordPluginProcessingLatency(latency.extensionPoint, latency.pluginType, latency.pluginName, latency.duration)
64+
}
65+
66+
wantPluginLatencies, err := os.Open("testdata/plugin_processing_latencies_metric")
67+
defer func() {
68+
if err := wantPluginLatencies.Close(); err != nil {
69+
t.Error(err)
70+
}
71+
}()
72+
if err != nil {
73+
t.Fatal(err)
74+
}
75+
if err := testutil.GatherAndCompare(crmetrics.Registry, wantPluginLatencies, "bbr_plugin_duration_seconds"); err != nil {
76+
t.Error(err)
77+
}
78+
})
79+
}
80+
}

‎pkg/bbr/metrics/testdata/plugin_processing_latencies_metric‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
# HELP bbr_plugin_duration_seconds [ALPHA] Plugin processing latency distribution in seconds for each extension point, plugin type and plugin name.
2+
# TYPE bbr_plugin_duration_seconds histogram
3+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0001"} 0
4+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0002"} 0
5+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.0005"} 0
6+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.001"} 0
7+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.002"} 0
8+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.005"} 1
9+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.01"} 1
10+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.02"} 1
11+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.05"} 1
12+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="0.1"} 1
13+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA",le="+Inf"} 1
14+
bbr_plugin_duration_seconds_sum{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA"} 0.005
15+
bbr_plugin_duration_seconds_count{extension_point="Request",plugin_name="PluginA",plugin_type="TestPluginA"} 1
16+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0001"} 1
17+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0002"} 1
18+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.0005"} 1
19+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.001"} 1
20+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.002"} 1
21+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.005"} 1
22+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.01"} 1
23+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.02"} 1
24+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.05"} 1
25+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="0.1"} 1
26+
bbr_plugin_duration_seconds_bucket{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB",le="+Inf"} 1
27+
bbr_plugin_duration_seconds_sum{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB"} 1e-05
28+
bbr_plugin_duration_seconds_count{extension_point="Request",plugin_name="PluginB",plugin_type="TestPluginB"} 1

0 commit comments

Comments
 (0)