Skip to content

Commit f4d6869

Browse files
committed
refactor: standardize metrics instrumentation
1 parent 4ddc6a8 commit f4d6869

39 files changed

Lines changed: 241 additions & 232 deletions

File tree

Makefile

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -52,7 +52,7 @@ define assert_clean
5252
fi
5353
endef
5454

55-
.PHONY: build build-all-linux build-runway-linux build-submitqueue-gateway-linux build-submitqueue-orchestrator-linux build-stovepipe-linux build-stovepipe-linux-debug check-gazelle check-mocks check-tidy clean clean-proto deps e2e-test fmt gazelle integration-test integration-test-submitqueue-consumer integration-test-extensions integration-test-submitqueue-gateway integration-test-submitqueue-orchestrator license-fix lint lint-fmt lint-license local-init-runway-queue-schema local-init-stovepipe-schemas local-runway-start local-runway-stop local-submitqueue-clean local-submitqueue-gateway-start local-submitqueue-gateway-stop local-init-submitqueue-schemas local-submitqueue-logs local-submitqueue-orchestrator-start local-submitqueue-orchestrator-stop local-submitqueue-ps local-submitqueue-restart local-submitqueue-start local-stop local-stovepipe-debug-start local-stovepipe-logs local-stovepipe-start local-stovepipe-stop mocks proto query-deps query-targets run-client-runway run-client-submitqueue-gateway run-client-submitqueue-orchestrator run-client-stovepipe run-queue-admin test test-no-cache tidy tidy-bazel tidy-go help
55+
.PHONY: build build-all-linux build-runway-linux build-submitqueue-gateway-linux build-submitqueue-orchestrator-linux build-stovepipe-linux build-stovepipe-linux-debug check-gazelle check-mocks check-tidy clean clean-proto deps e2e-test fmt gazelle integration-test integration-test-submitqueue-consumer integration-test-extensions integration-test-submitqueue-gateway integration-test-submitqueue-orchestrator license-fix lint lint-fmt lint-license lint-metrics local-init-runway-queue-schema local-init-stovepipe-schemas local-runway-start local-runway-stop local-submitqueue-clean local-submitqueue-gateway-start local-submitqueue-gateway-stop local-init-submitqueue-schemas local-submitqueue-logs local-submitqueue-orchestrator-start local-submitqueue-orchestrator-stop local-submitqueue-ps local-submitqueue-restart local-submitqueue-start local-stop local-stovepipe-debug-start local-stovepipe-logs local-stovepipe-start local-stovepipe-stop mocks proto query-deps query-targets run-client-runway run-client-submitqueue-gateway run-client-submitqueue-orchestrator run-client-stovepipe run-queue-admin test test-no-cache tidy tidy-bazel tidy-go help
5656

5757

5858
build: ## Build all services and examples
@@ -170,7 +170,7 @@ integration-test-submitqueue-orchestrator: build-submitqueue-orchestrator-linux
170170
license-fix: ## Add missing license headers to source files
171171
@$(BAZEL) run //tool/linter/licenseheader -- --fix
172172

173-
lint: lint-fmt lint-license ## Run all linters
173+
lint: lint-fmt lint-license lint-metrics ## Run all linters
174174
@echo "All lint checks passed."
175175

176176
lint-fmt: fmt ## Check code formatting (fails if unformatted)
@@ -180,6 +180,14 @@ lint-fmt: fmt ## Check code formatting (fails if unformatted)
180180
lint-license: ## Check license headers on all source files
181181
@$(BAZEL) run //tool/linter/licenseheader -- --check
182182

183+
lint-metrics: ## Check metrics use the platform framework
184+
@violations="$$(git grep -n -E '\.(Counter|Gauge|Histogram|Timer)\(' -- '*.go' ':(exclude)platform/metrics/metrics.go' || true)"; \
185+
if [ -n "$$violations" ]; then \
186+
echo "Direct Tally metric construction is not allowed outside platform/metrics:" >&2; \
187+
echo "$$violations" >&2; \
188+
exit 1; \
189+
fi
190+
183191
local-submitqueue-clean: ## Stop and remove all local services, volumes, and images
184192
@echo "Cleaning all services and data..."
185193
@$(COMPOSE) -f $(COMPOSE_FILE) -p $(SUBMITQUEUE_LOCAL_PROJECT) down -v --rmi local

platform/consumer/README.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -120,6 +120,8 @@ When the consumer is wired with `errs.AlwaysRetryableProcessor` (DLQ reconciliat
120120

121121
The consumer records controller operations with `process.start` and `process.finish`. The finish histogram records both latency and completion count with `result=success|error|cancel`; error and cancellation series also include `origin=infra|infra_retryable|user` and `dependency=yes|no`. These dimensions are added after error processing, so they describe the classified error that drives ack, nack, or reject behavior rather than the controller's raw return value. The lifecycle histogram count replaces separate received, processed, and controller-error counters.
122122

123+
The consumer also owns lifecycle metrics for the resulting `ack`, `nack`, or `reject` transport operation. Queue controllers should emit only domain-specific event counters; they must not duplicate the consumer-owned `process` lifecycle metrics.
124+
123125
## Lifecycle
124126

125127
1. **Register** controllers before starting.

platform/consumer/consumer.go

Lines changed: 17 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -83,12 +83,14 @@ type activeSubscription struct {
8383
// consumers (per-node classifier walk that preserves controller-attached
8484
// framework wraps), or errs.AlwaysRetryableProcessor for narrowly-scoped
8585
// consumers such as DLQ reconciliation that must redeliver on any failure.
86-
// processor must not be nil; callers that genuinely want no transformation
87-
// can pass errs.NewClassifierProcessor() with no classifiers.
86+
// scope is used as provided so wiring can distinguish primary and DLQ consumers
87+
// without introducing duplicate consumer sub-scopes. processor must not be nil;
88+
// callers that genuinely want no transformation can pass
89+
// errs.NewClassifierProcessor() with no classifiers.
8890
func New(logger *zap.SugaredLogger, scope tally.Scope, registry TopicRegistry, processor errs.ErrorProcessor) Consumer {
8991
return &consumer{
9092
logger: logger,
91-
metricsScope: scope.SubScope("consumer"),
93+
metricsScope: scope,
9294
registry: registry,
9395
processor: processor,
9496
subscriptions: make(map[TopicKey]*activeSubscription),
@@ -394,14 +396,16 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
394396
)
395397

396398
// Reject moves to DLQ (or acks if DLQ disabled)
397-
if rejectErr := delivery.Reject(ctx, err.Error()); rejectErr != nil {
399+
rejectOp := metrics.Begin(controllerScope, "reject", metrics.StorageLatencyBuckets)
400+
rejectErr := delivery.Reject(ctx, err.Error())
401+
rejectOp.Complete(rejectErr)
402+
if rejectErr != nil {
398403
m.logger.Errorw("failed to reject non-retryable message",
399404
"controller", controller.Name(),
400405
"topic_key", controller.TopicKey(),
401406
"message_id", msg.ID,
402407
"error", rejectErr,
403408
)
404-
metrics.NamedCounter(controllerScope, opName, "reject_errors", 1)
405409
}
406410
return
407411
}
@@ -424,48 +428,34 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
424428
)
425429

426430
// Nack with no delay - let visibility timeout handle retry delay
427-
nackStart := time.Now()
428-
if nackErr := delivery.Nack(ctx, 0); nackErr != nil {
431+
nackOp := metrics.Begin(controllerScope, "nack", metrics.StorageLatencyBuckets)
432+
nackErr := delivery.Nack(ctx, 0)
433+
nackOp.Complete(nackErr)
434+
if nackErr != nil {
429435
m.logger.Errorw("failed to nack message",
430436
"controller", controller.Name(),
431437
"topic_key", topicKey,
432438
"message_id", msg.ID,
433439
"error", nackErr,
434440
)
435-
metrics.NamedCounter(controllerScope, opName, "nack_errors", 1)
436-
} else {
437-
metrics.NamedCounter(controllerScope, opName, "nack_count", 1)
438-
metrics.NamedHistogram(controllerScope, opName, "ack_nack_latency", metrics.StorageLatencyBuckets,
439-
metrics.NewTag("operation", "nack"),
440-
metrics.NewTag("success", "true"),
441-
).RecordDuration(time.Since(nackStart))
442441
}
443442
return
444443
}
445444

446445
// Controller succeeded - ack message
447-
ackStart := time.Now()
448-
if ackErr := delivery.Ack(ctx); ackErr != nil {
446+
ackOp := metrics.Begin(controllerScope, "ack", metrics.StorageLatencyBuckets)
447+
ackErr := delivery.Ack(ctx)
448+
ackOp.Complete(ackErr)
449+
if ackErr != nil {
449450
m.logger.Errorw("failed to ack message",
450451
"controller", controller.Name(),
451452
"topic_key", topicKey,
452453
"message_id", msg.ID,
453454
"error", ackErr,
454455
)
455-
metrics.NamedCounter(controllerScope, opName, "ack_errors", 1)
456-
metrics.NamedHistogram(controllerScope, opName, "ack_nack_latency", metrics.StorageLatencyBuckets,
457-
metrics.NewTag("operation", "ack"),
458-
metrics.NewTag("success", "false"),
459-
).RecordDuration(time.Since(ackStart))
460456
return
461457
}
462458

463-
metrics.NamedCounter(controllerScope, opName, "ack_count", 1)
464-
metrics.NamedHistogram(controllerScope, opName, "ack_nack_latency", metrics.StorageLatencyBuckets,
465-
metrics.NewTag("operation", "ack"),
466-
metrics.NewTag("success", "true"),
467-
).RecordDuration(time.Since(ackStart))
468-
469459
m.logger.Debugw("message processed successfully",
470460
"controller", controller.Name(),
471461
"topic_key", topicKey,

platform/consumer/consumer_test.go

Lines changed: 63 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -117,6 +117,10 @@ func setupDelivery(del *queuemock.MockDelivery, msg entityqueue.Message, ackErr,
117117
close(done)
118118
return nackErr
119119
}).MaxTimes(1)
120+
del.EXPECT().Reject(gomock.Any(), gomock.Any()).DoAndReturn(func(ctx context.Context, reason string) error {
121+
close(done)
122+
return nil
123+
}).MaxTimes(1)
120124
return done
121125
}
122126

@@ -436,20 +440,20 @@ func TestConsumer_Stop(t *testing.T) {
436440

437441
func TestConsumer_ObservabilityTags(t *testing.T) {
438442
tests := []struct {
439-
name string
440-
handlerError error
441-
nackError error
442-
processor errs.ErrorProcessor
443-
expectedTags map[string]string
444-
expectAckCount bool
443+
name string
444+
handlerError error
445+
nackError error
446+
processor errs.ErrorProcessor
447+
expectedTags map[string]string
448+
transport string
445449
}{
446450
{
447-
name: "success with ack",
448-
handlerError: nil,
449-
nackError: nil,
450-
processor: errs.NewClassifierProcessor(),
451-
expectedTags: map[string]string{"result": "success"},
452-
expectAckCount: true,
451+
name: "success with ack",
452+
handlerError: nil,
453+
nackError: nil,
454+
processor: errs.NewClassifierProcessor(),
455+
expectedTags: map[string]string{"result": "success"},
456+
transport: "ack",
453457
},
454458
{
455459
name: "classified failure with nack",
@@ -463,7 +467,7 @@ func TestConsumer_ObservabilityTags(t *testing.T) {
463467
"origin": "infra_retryable",
464468
"dependency": "yes",
465469
},
466-
expectAckCount: false,
470+
transport: "nack",
467471
},
468472
{
469473
name: "classified cancellation with nack",
@@ -477,7 +481,18 @@ func TestConsumer_ObservabilityTags(t *testing.T) {
477481
"origin": "infra_retryable",
478482
"dependency": "no",
479483
},
480-
expectAckCount: false,
484+
transport: "nack",
485+
},
486+
{
487+
name: "user failure with reject",
488+
handlerError: errs.NewUserError(fmt.Errorf("invalid request")),
489+
processor: errs.NewClassifierProcessor(),
490+
expectedTags: map[string]string{
491+
"result": "error",
492+
"origin": "user",
493+
"dependency": "no",
494+
},
495+
transport: "reject",
481496
},
482497
}
483498

@@ -528,6 +543,7 @@ func TestConsumer_ObservabilityTags(t *testing.T) {
528543

529544
var foundLatency bool
530545
for _, histogram := range histograms {
546+
assert.NotContains(t, histogram.Name(), "consumer.consumer")
531547
if strings.Contains(histogram.Name(), "process.finish") {
532548
foundLatency = true
533549
tags := histogram.Tags()
@@ -538,27 +554,32 @@ func TestConsumer_ObservabilityTags(t *testing.T) {
538554
}
539555
assert.True(t, foundLatency, "Should have process.finish metric")
540556

557+
var foundTransport bool
558+
for _, histogram := range histograms {
559+
if strings.Contains(histogram.Name(), tt.transport+".finish") {
560+
foundTransport = true
561+
assert.Equal(t, "success", histogram.Tags()["result"])
562+
}
563+
assert.NotContains(t, histogram.Name(), "ack_nack_latency")
564+
}
565+
assert.True(t, foundTransport, "Should have %s.finish metric", tt.transport)
566+
541567
counters := snapshot.Counters()
542568
for _, duplicate := range []string{
543569
"messages_received",
544570
"messages_processed",
545571
"non_retryable_errors",
546572
"controller_errors",
573+
"ack_count",
574+
"ack_errors",
575+
"nack_count",
576+
"nack_errors",
577+
"reject_errors",
547578
} {
548579
for _, counter := range counters {
549580
assert.NotContains(t, counter.Name(), duplicate)
550581
}
551582
}
552-
if tt.expectAckCount {
553-
var foundAck bool
554-
for _, counter := range counters {
555-
if strings.Contains(counter.Name(), "ack_count") {
556-
foundAck = true
557-
assert.Greater(t, counter.Value(), int64(0))
558-
}
559-
}
560-
assert.True(t, foundAck, "Should have ack_count metric")
561-
}
562583

563584
_ = testC.Stop(30000)
564585
})
@@ -616,7 +637,7 @@ func TestControllerClassificationTags(t *testing.T) {
616637
}
617638
}
618639

619-
func TestConsumer_AckNackLatencyTracking(t *testing.T) {
640+
func TestConsumer_AckLifecycleMetrics(t *testing.T) {
620641
ctrl := gomock.NewController(t)
621642
logger := zaptest.NewLogger(t).Sugar()
622643
scope := tally.NewTestScope("consumer", nil)
@@ -654,14 +675,21 @@ func TestConsumer_AckNackLatencyTracking(t *testing.T) {
654675
<-done
655676

656677
snapshot := scope.Snapshot()
657-
assert.NotEmpty(t, snapshot.Histograms(), "Should have histogram metrics for latency tracking")
658-
assert.NotEmpty(t, snapshot.Counters(), "Should have counter metrics")
678+
histograms := snapshot.Histograms()
679+
var foundAck bool
680+
for _, histogram := range histograms {
681+
if strings.Contains(histogram.Name(), "ack.finish") {
682+
foundAck = true
683+
assert.Equal(t, "success", histogram.Tags()["result"])
684+
}
685+
}
686+
assert.True(t, foundAck, "Should have successful ack.finish metric")
659687

660688
err = c.Stop(30000)
661689
require.NoError(t, err)
662690
}
663691

664-
func TestConsumer_ErrorMetrics(t *testing.T) {
692+
func TestConsumer_NackLifecycleMetrics(t *testing.T) {
665693
ctrl := gomock.NewController(t)
666694
logger := zaptest.NewLogger(t).Sugar()
667695
scope := tally.NewTestScope("consumer", nil)
@@ -701,16 +729,15 @@ func TestConsumer_ErrorMetrics(t *testing.T) {
701729
<-done
702730

703731
snapshot := scope.Snapshot()
704-
counters := snapshot.Counters()
705-
706-
var hasErrorMetrics bool
707-
for _, counter := range counters {
708-
if strings.Contains(counter.Name(), "errors") {
709-
hasErrorMetrics = true
710-
break
732+
histograms := snapshot.Histograms()
733+
var foundNackError bool
734+
for _, histogram := range histograms {
735+
if strings.Contains(histogram.Name(), "nack.finish") {
736+
foundNackError = true
737+
assert.Equal(t, "error", histogram.Tags()["result"])
711738
}
712739
}
713-
assert.True(t, hasErrorMetrics, "Should track error metrics")
740+
assert.True(t, foundNackError, "Should have failed nack.finish metric")
714741

715742
err = c.Stop(30000)
716743
require.NoError(t, err)

platform/consumer/controller.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -89,6 +89,7 @@ func (d *deliveryWrapper) Metadata() map[string]string {
8989
// The Controller interface enables clean separation of concerns:
9090
// - Controller focuses on business logic (deserialize, process, return error status)
9191
// - Consumer handles infrastructure (subscription, ack/nack, metrics, lifecycle)
92+
// Controllers may emit domain event counters, but must not duplicate the consumer-owned Process lifecycle metrics.
9293
// The implementation of the controller should be idempotent and stateless. The controller is expected to be retried for the same message multiple times and should process side effects gracefully.
9394
// The implementation must be thread-safe.
9495
type Controller interface {

platform/extension/messagequeue/mysql/subscriber.go

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -747,13 +747,18 @@ func (w *partitionWorker) run(ctx context.Context) {
747747
// Partition leasing guarantees a single writer, so the TOCTOU gap between
748748
// GetDeliveryState and MarkDelivered cannot cause incorrect behavior — no other
749749
// worker can mutate the same (consumer_group, topic, partition_key, offset).
750-
func (w *partitionWorker) pollAndDeliver(ctx context.Context) error {
751-
start := time.Now()
750+
func (w *partitionWorker) pollAndDeliver(ctx context.Context) (retErr error) {
752751
s := w.subscriber
753752
sub := w.sub
754753
cfg := sub.config
755754
partitionKey := w.partitionKey
756755

756+
op := metrics.Begin(s.scope, "poll", metrics.StorageLatencyBuckets,
757+
metrics.NewTag("topic", sub.topic),
758+
metrics.NewTag("partition_key", partitionKey),
759+
)
760+
defer func() { op.Complete(retErr) }()
761+
757762
// Initialize offset for this partition once per worker lifetime
758763
if !w.offsetInitialized {
759764
if err := s.offsetStore.Initialize(ctx, sub.topic, partitionKey, cfg.ConsumerGroup); err != nil {
@@ -912,15 +917,10 @@ func (w *partitionWorker) pollAndDeliver(ctx context.Context) error {
912917

913918
// Record poll metrics
914919
if messageCount > 0 {
915-
elapsed := time.Since(start)
916920
metrics.NamedCounter(s.scope, "poll", "messages_delivered", int64(messageCount),
917921
metrics.NewTag("topic", sub.topic),
918922
metrics.NewTag("partition_key", partitionKey),
919923
)
920-
metrics.NamedHistogram(s.scope, "poll", "latency", metrics.StorageLatencyBuckets,
921-
metrics.NewTag("topic", sub.topic),
922-
metrics.NewTag("partition_key", partitionKey),
923-
).RecordDuration(elapsed)
924924
}
925925

926926
return nil

0 commit comments

Comments
 (0)