Skip to content

Commit 2c6fc98

Browse files
miledxzmiledxz
committed
Add event processing histogram metric (nginx#1134)
Problem: NGF does not measure how long it takes to process an event batch. Solution: Add a new histogram metric event_batch_processing_milliseconds, that measures the time it takes to process an event batch. Also adds a debug log statement with the same information so we can debug spikes in processing time.
1 parent 916787d commit 2c6fc98

File tree

17 files changed

+234
-152
lines changed

17 files changed

+234
-152
lines changed

‎docs/monitoring.md

+3
Original file line numberDiff line numberDiff line change
@@ -92,6 +92,9 @@ NGINX Gateway Fabric exports the following metrics:
9292
- nginx_stale_config. 1 means NGF failed to configure NGINX with the latest version of the configuration, which means
9393
NGINX is running with a stale version.
9494
- nginx_last_reload_milliseconds. Duration in milliseconds of NGINX reloads (histogram).
95+
- event_batch_processing_milliseconds: Duration in milliseconds of event batch processing (histogram), which is the
96+
time it takes NGF to process batches of Kubernetes events (changes to cluster resources). Note that NGF processes
97+
events in batches, and while processing the current batch, it accumulates events for the next batch.
9598
- These metrics have the namespace `nginx_gateway_fabric`, and include the label `class` which is set to the
9699
Gateway class of NGF. For example, `nginx_gateway_fabric_nginx_reloads_total{class="nginx"}`.
97100

‎internal/framework/events/eventsfakes/fake_event_handler.go

+13-10
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎internal/framework/events/handler.go

+3-1
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@ package events
22

33
import (
44
"context"
5+
6+
"github.com/go-logr/logr"
57
)
68

79
//go:generate go run github.com/maxbrunsfeld/counterfeiter/v6 . EventHandler
@@ -10,5 +12,5 @@ import (
1012
type EventHandler interface {
1113
// HandleEventBatch handles a batch of events.
1214
// EventBatch can include duplicated events.
13-
HandleEventBatch(ctx context.Context, batch EventBatch)
15+
HandleEventBatch(ctx context.Context, logger logr.Logger, batch EventBatch)
1416
}

‎internal/framework/events/loop.go

+9-3
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,9 @@ type EventLoop struct {
3434
// The batches are swapped before starting the handler goroutine.
3535
currentBatch EventBatch
3636
nextBatch EventBatch
37+
38+
// the ID of the current batch
39+
currentBatchID int
3740
}
3841

3942
// NewEventLoop creates a new EventLoop.
@@ -63,11 +66,14 @@ func (el *EventLoop) Start(ctx context.Context) error {
6366

6467
handleBatch := func() {
6568
go func(batch EventBatch) {
66-
el.logger.Info("Handling events from the batch", "total", len(batch))
69+
el.currentBatchID++
70+
batchLogger := el.logger.WithName("eventHandler").WithValues("batchID", el.currentBatchID)
71+
72+
batchLogger.Info("Handling events from the batch", "total", len(batch))
6773

68-
el.handler.HandleEventBatch(ctx, batch)
74+
el.handler.HandleEventBatch(ctx, batchLogger, batch)
6975

70-
el.logger.Info("Finished handling the batch")
76+
batchLogger.Info("Finished handling the batch")
7177
handlingDone <- struct{}{}
7278
}(el.currentBatch)
7379
}

‎internal/framework/events/loop_test.go

+6-5
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import (
44
"context"
55
"errors"
66

7+
"github.com/go-logr/logr"
78
. "github.com/onsi/ginkgo/v2"
89
. "github.com/onsi/gomega"
910
"sigs.k8s.io/controller-runtime/pkg/log/zap"
@@ -47,7 +48,7 @@ var _ = Describe("EventLoop", func() {
4748

4849
// Ensure the first batch is handled
4950
Eventually(fakeHandler.HandleEventBatchCallCount).Should(Equal(1))
50-
_, batch = fakeHandler.HandleEventBatchArgsForCall(0)
51+
_, _, batch = fakeHandler.HandleEventBatchArgsForCall(0)
5152

5253
var expectedBatch events.EventBatch = []interface{}{"event0"}
5354
Expect(batch).Should(Equal(expectedBatch))
@@ -70,7 +71,7 @@ var _ = Describe("EventLoop", func() {
7071
eventCh <- e
7172

7273
Eventually(fakeHandler.HandleEventBatchCallCount).Should(Equal(2))
73-
_, batch := fakeHandler.HandleEventBatchArgsForCall(1)
74+
_, _, batch := fakeHandler.HandleEventBatchArgsForCall(1)
7475

7576
var expectedBatch events.EventBatch = []interface{}{e}
7677
Expect(batch).Should(Equal(expectedBatch))
@@ -82,7 +83,7 @@ var _ = Describe("EventLoop", func() {
8283

8384
// The func below will pause the handler goroutine while it is processing the batch with e1 until
8485
// sentSecondAndThirdEvents is closed. This way we can add e2 and e3 to the current batch in the meantime.
85-
fakeHandler.HandleEventBatchCalls(func(ctx context.Context, batch events.EventBatch) {
86+
fakeHandler.HandleEventBatchCalls(func(ctx context.Context, logger logr.Logger, batch events.EventBatch) {
8687
close(firstHandleEventBatchCallInProgress)
8788
<-sentSecondAndThirdEvents
8889
})
@@ -106,14 +107,14 @@ var _ = Describe("EventLoop", func() {
106107
close(sentSecondAndThirdEvents)
107108

108109
Eventually(fakeHandler.HandleEventBatchCallCount).Should(Equal(3))
109-
_, batch := fakeHandler.HandleEventBatchArgsForCall(1)
110+
_, _, batch := fakeHandler.HandleEventBatchArgsForCall(1)
110111

111112
var expectedBatch events.EventBatch = []interface{}{e1}
112113

113114
// the first HandleEventBatch() call must have handled a batch with e1
114115
Expect(batch).Should(Equal(expectedBatch))
115116

116-
_, batch = fakeHandler.HandleEventBatchArgsForCall(2)
117+
_, _, batch = fakeHandler.HandleEventBatchArgsForCall(2)
117118

118119
expectedBatch = []interface{}{e2, e3}
119120
// the second HandleEventBatch() call must have handled a batch with e2 and e3

‎internal/mode/provisioner/handler.go

+5-8
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,6 @@ type eventHandler struct {
2727

2828
statusUpdater status.Updater
2929
k8sClient client.Client
30-
logger logr.Logger
3130

3231
staticModeDeploymentYAML []byte
3332

@@ -38,7 +37,6 @@ func newEventHandler(
3837
gcName string,
3938
statusUpdater status.Updater,
4039
k8sClient client.Client,
41-
logger logr.Logger,
4240
staticModeDeploymentYAML []byte,
4341
) *eventHandler {
4442
return &eventHandler{
@@ -47,7 +45,6 @@ func newEventHandler(
4745
statusUpdater: statusUpdater,
4846
gcName: gcName,
4947
k8sClient: k8sClient,
50-
logger: logger,
5148
staticModeDeploymentYAML: staticModeDeploymentYAML,
5249
gatewayNextID: 1,
5350
}
@@ -80,7 +77,7 @@ func (h *eventHandler) setGatewayClassStatuses(ctx context.Context) {
8077
h.statusUpdater.Update(ctx, statuses)
8178
}
8279

83-
func (h *eventHandler) ensureDeploymentsMatchGateways(ctx context.Context) {
80+
func (h *eventHandler) ensureDeploymentsMatchGateways(ctx context.Context, logger logr.Logger) {
8481
var gwsWithoutDeps, removedGwsWithDeps []types.NamespacedName
8582

8683
for nsname, gw := range h.store.gateways {
@@ -116,7 +113,7 @@ func (h *eventHandler) ensureDeploymentsMatchGateways(ctx context.Context) {
116113

117114
h.provisions[nsname] = deployment
118115

119-
h.logger.Info(
116+
logger.Info(
120117
"Created deployment",
121118
"deployment", client.ObjectKeyFromObject(deployment),
122119
"gateway", nsname,
@@ -134,18 +131,18 @@ func (h *eventHandler) ensureDeploymentsMatchGateways(ctx context.Context) {
134131

135132
delete(h.provisions, nsname)
136133

137-
h.logger.Info(
134+
logger.Info(
138135
"Deleted deployment",
139136
"deployment", client.ObjectKeyFromObject(deployment),
140137
"gateway", nsname,
141138
)
142139
}
143140
}
144141

145-
func (h *eventHandler) HandleEventBatch(ctx context.Context, batch events.EventBatch) {
142+
func (h *eventHandler) HandleEventBatch(ctx context.Context, logger logr.Logger, batch events.EventBatch) {
146143
h.store.update(batch)
147144
h.setGatewayClassStatuses(ctx)
148-
h.ensureDeploymentsMatchGateways(ctx)
145+
h.ensureDeploymentsMatchGateways(ctx, logger)
149146
}
150147

151148
func (h *eventHandler) generateDeploymentID() string {

‎internal/mode/provisioner/handler_test.go

+10-13
Original file line numberDiff line numberDiff line change
@@ -96,7 +96,7 @@ var _ = Describe("handler", func() {
9696
Resource: gc,
9797
},
9898
}
99-
handler.HandleEventBatch(context.Background(), batch)
99+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
100100

101101
// Ensure GatewayClass is accepted
102102

@@ -126,7 +126,7 @@ var _ = Describe("handler", func() {
126126
},
127127
}
128128

129-
handler.HandleEventBatch(context.Background(), batch)
129+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
130130

131131
depNsName := types.NamespacedName{
132132
Namespace: "nginx-gateway",
@@ -156,7 +156,7 @@ var _ = Describe("handler", func() {
156156
}
157157

158158
handle := func() {
159-
handler.HandleEventBatch(context.Background(), batch)
159+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
160160
}
161161

162162
Expect(handle).Should(Panic())
@@ -179,7 +179,6 @@ var _ = Describe("handler", func() {
179179
gcName,
180180
statusUpdater,
181181
k8sclient,
182-
zap.New(),
183182
embeddedfiles.StaticModeDeploymentYAML,
184183
)
185184
})
@@ -217,7 +216,7 @@ var _ = Describe("handler", func() {
217216
},
218217
}
219218

220-
handler.HandleEventBatch(context.Background(), batch)
219+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
221220
deps := &v1.DeploymentList{}
222221

223222
err := k8sclient.List(context.Background(), deps)
@@ -237,7 +236,7 @@ var _ = Describe("handler", func() {
237236
},
238237
}
239238

240-
handler.HandleEventBatch(context.Background(), batch)
239+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
241240

242241
deps := &v1.DeploymentList{}
243242

@@ -266,7 +265,7 @@ var _ = Describe("handler", func() {
266265
},
267266
}
268267

269-
handler.HandleEventBatch(context.Background(), batch)
268+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
270269

271270
deps := &v1.DeploymentList{}
272271
err := k8sclient.List(context.Background(), deps)
@@ -295,7 +294,7 @@ var _ = Describe("handler", func() {
295294
},
296295
}
297296

298-
handler.HandleEventBatch(context.Background(), batch)
297+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
299298

300299
unknownGC := &v1beta1.GatewayClass{}
301300
err = k8sclient.Get(context.Background(), client.ObjectKeyFromObject(gc), unknownGC)
@@ -330,7 +329,6 @@ var _ = Describe("handler", func() {
330329
gcName,
331330
statusUpdater,
332331
k8sclient,
333-
zap.New(),
334332
embeddedfiles.StaticModeDeploymentYAML,
335333
)
336334
})
@@ -340,7 +338,7 @@ var _ = Describe("handler", func() {
340338
batch := []interface{}{e}
341339

342340
handle := func() {
343-
handler.HandleEventBatch(context.TODO(), batch)
341+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
344342
}
345343

346344
Expect(handle).Should(Panic())
@@ -408,7 +406,7 @@ var _ = Describe("handler", func() {
408406
}
409407

410408
handle := func() {
411-
handler.HandleEventBatch(context.Background(), batch)
409+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
412410
}
413411

414412
Expect(handle).Should(Panic())
@@ -429,7 +427,7 @@ var _ = Describe("handler", func() {
429427
}
430428

431429
handle := func() {
432-
handler.HandleEventBatch(context.Background(), batch)
430+
handler.HandleEventBatch(context.Background(), zap.New(), batch)
433431
}
434432

435433
Expect(handle).Should(Panic())
@@ -442,7 +440,6 @@ var _ = Describe("handler", func() {
442440
gcName,
443441
statusUpdater,
444442
k8sclient,
445-
zap.New(),
446443
[]byte("broken YAML"),
447444
)
448445

‎internal/mode/provisioner/manager.go

-1
Original file line numberDiff line numberDiff line change
@@ -107,7 +107,6 @@ func StartManager(cfg Config) error {
107107
cfg.GatewayClassName,
108108
statusUpdater,
109109
mgr.GetClient(),
110-
cfg.Logger.WithName("eventHandler"),
111110
embeddedfiles.StaticModeDeploymentYAML,
112111
)
113112

0 commit comments

Comments
 (0)