feat(go): expose fast writer stage latency histogram

go/vehicle-gateway/cmd/nats-fast-writer/main.go

@@ -213,7 +213,7 @@ func runFastWorker(ctx context.Context, logger *slog.Logger, registry *metrics.R
 		for _, msg := range msgs {
 			msg := msg
 			operationCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), cfg.OperationWait)
-			err := processFastMessage(operationCtx, appender, updater, &fastMessage{
+			err := processFastMessage(operationCtx, registry, appender, updater, &fastMessage{
 				subject: msg.Subject,
 				data:    msg.Data,
 				ack: func() error {
@@ -235,7 +235,9 @@ type natsPullSubscription interface {
 	Fetch(int, ...nats.PullOpt) ([]*nats.Msg, error)
 }
 
-func processFastMessage(ctx context.Context, appender fastAppender, updater fastUpdater, msg *fastMessage) error {
+var fastWriterStageDurationBucketsMS = []float64{1, 5, 10, 25, 50, 100, 250, 500, 1000, 5000}
+
+func processFastMessage(ctx context.Context, registry *metrics.Registry, appender fastAppender, updater fastUpdater, msg *fastMessage) error {
 	var env envelope.FrameEnvelope
 	if err := json.Unmarshal(msg.data, &env); err != nil {
 		if msg.ack != nil {
@@ -243,14 +245,23 @@ func processFastMessage(ctx context.Context, appender fastAppender, updater fast
 		}
 		return nil
 	}
-	if err := appender.AppendAll(ctx, env); err != nil {
+	started := time.Now()
+	err := appender.AppendAll(ctx, env)
+	recordFastWriterStageDuration(registry, msg.subject, "tdengine", statusFromError(err), time.Since(started))
+	if err != nil {
 		return fmt.Errorf("tdengine append: %w", err)
 	}
-	if err := updater.FastUpdate(ctx, env); err != nil {
+	started = time.Now()
+	err = updater.FastUpdate(ctx, env)
+	recordFastWriterStageDuration(registry, msg.subject, "redis", statusFromError(err), time.Since(started))
+	if err != nil {
 		return fmt.Errorf("redis fast update: %w", err)
 	}
 	if msg.ack != nil {
-		if err := msg.ack(); err != nil {
+		started = time.Now()
+		err = msg.ack()
+		recordFastWriterStageDuration(registry, msg.subject, "ack", statusFromError(err), time.Since(started))
+		if err != nil {
 			return fmt.Errorf("nats ack: %w", err)
 		}
 	}
@@ -288,6 +299,24 @@ func addFastMetric(registry *metrics.Registry, subject string, status string) {
 	registry.IncCounter("vehicle_fast_writer_messages_total", metrics.Labels{"subject": subject, "status": status})
 }
 
+func recordFastWriterStageDuration(registry *metrics.Registry, subject string, stage string, status string, elapsed time.Duration) {
+	if registry == nil {
+		return
+	}
+	registry.ObserveHistogram("vehicle_fast_writer_stage_duration_ms_histogram", metrics.Labels{
+		"subject": subject,
+		"stage":   stage,
+		"status":  status,
+	}, fastWriterStageDurationBucketsMS, float64(elapsed.Milliseconds()))
+}
+
+func statusFromError(err error) string {
+	if err != nil {
+		return "error"
+	}
+	return "ok"
+}
+
 func env(key string, fallback string) string {
 	value := strings.TrimSpace(os.Getenv(key))
 	if value == "" {

go/vehicle-gateway/cmd/nats-fast-writer/main_test.go

@@ -3,9 +3,11 @@ package main
 import (
 	"context"
 	"errors"
+	"strings"
 	"testing"
 
 	"lingniu-vehicle-ingest/go/vehicle-gateway/internal/envelope"
+	"lingniu-vehicle-ingest/go/vehicle-gateway/internal/metrics"
 )
 
 func TestProcessFastMessageWritesTDengineAndRedisBeforeAck(t *testing.T) {
@@ -22,7 +24,7 @@ func TestProcessFastMessageWritesTDengineAndRedisBeforeAck(t *testing.T) {
 		return nil
 	}}
 
-	if err := processFastMessage(context.Background(), appender, updater, msg); err != nil {
+	if err := processFastMessage(context.Background(), nil, appender, updater, msg); err != nil {
 		t.Fatalf("processFastMessage() error = %v", err)
 	}
 	if appender.count != 1 || updater.count != 1 || ackCount != 1 {
@@ -44,7 +46,7 @@ func TestProcessFastMessageDoesNotAckWhenRedisFails(t *testing.T) {
 		return nil
 	}}
 
-	if err := processFastMessage(context.Background(), appender, updater, msg); err == nil {
+	if err := processFastMessage(context.Background(), nil, appender, updater, msg); err == nil {
 		t.Fatal("processFastMessage() error = nil, want redis failure")
 	}
 	if ackCount != 0 {
@@ -52,6 +54,32 @@ func TestProcessFastMessageDoesNotAckWhenRedisFails(t *testing.T) {
 	}
 }
 
+func TestProcessFastMessageRecordsStageDurationMetrics(t *testing.T) {
+	env := envelope.FrameEnvelope{Protocol: envelope.ProtocolJT808, VIN: "VIN001", EventID: "evt-3"}
+	payload, err := env.MarshalJSONBytes()
+	if err != nil {
+		t.Fatal(err)
+	}
+	registry := metrics.NewRegistry()
+	msg := &fastMessage{subject: "vehicle.raw.go.jt808.v1", data: payload, ack: func() error { return nil }}
+
+	if err := processFastMessage(context.Background(), registry, &recordingFastAppender{}, &recordingFastUpdater{}, msg); err != nil {
+		t.Fatalf("processFastMessage() error = %v", err)
+	}
+
+	text := registry.Render()
+	for _, want := range []string{
+		`vehicle_fast_writer_stage_duration_ms_histogram_bucket{le="+Inf",stage="tdengine",status="ok",subject="vehicle.raw.go.jt808.v1"} 1`,
+		`vehicle_fast_writer_stage_duration_ms_histogram_count{stage="tdengine",status="ok",subject="vehicle.raw.go.jt808.v1"} 1`,
+		`vehicle_fast_writer_stage_duration_ms_histogram_bucket{le="+Inf",stage="redis",status="ok",subject="vehicle.raw.go.jt808.v1"} 1`,
+		`vehicle_fast_writer_stage_duration_ms_histogram_bucket{le="+Inf",stage="ack",status="ok",subject="vehicle.raw.go.jt808.v1"} 1`,
+	} {
+		if !strings.Contains(text, want) {
+			t.Fatalf("fast writer stage metric missing %s:\n%s", want, text)
+		}
+	}
+}
+
 type recordingFastAppender struct {
 	count int
 	err   error