From 2db05d100d54dba0c3c36bd75001fabdd100ddfa Mon Sep 17 00:00:00 2001 From: lingniu Date: Fri, 3 Jul 2026 19:12:58 +0800 Subject: [PATCH] feat(go): expose fast writer stage latency histogram --- docs/ops/100k-capacity-baseline.md | 1 + docs/ops/go-service-observability.md | 1 + docs/ops/go-vehicle-ingest-memory.md | 12 ++++++ docs/ops/vehicle-ingest-runbook.md | 1 + .../cmd/nats-fast-writer/main.go | 39 ++++++++++++++++--- .../cmd/nats-fast-writer/main_test.go | 32 ++++++++++++++- 6 files changed, 79 insertions(+), 7 deletions(-) diff --git a/docs/ops/100k-capacity-baseline.md b/docs/ops/100k-capacity-baseline.md index e6094c4d..22fb2afd 100644 --- a/docs/ops/100k-capacity-baseline.md +++ b/docs/ops/100k-capacity-baseline.md @@ -76,6 +76,7 @@ systemd gateway 已配置 `LimitNOFILE=1048576`，需要持续保持。 | NATS bridge | `vehicle_bridge_nats_consumer_pending` | burst 后下降 | | NATS bridge | `vehicle_bridge_batch_pending_messages` | 稳态接近 0，burst 后下降 | | NATS bridge | `vehicle_bridge_batch_duration_ms_histogram_bucket` | p99 不持续上升 | +| NATS fast writer | `vehicle_fast_writer_stage_duration_ms_histogram_bucket` | TDengine/Redis/ack 各阶段 p99 不持续上升 | | Kafka consumers | `vehicle_*_kafka_lag` | 稳态为 0，burst 后下降 | | Realtime Redis | `vehicle_realtime_store_update_duration_ms_histogram_bucket{store="redis"}` | p99 毫秒级且不持续上升 | | Realtime MySQL | `vehicle_realtime_store_update_duration_ms_histogram_bucket{store="mysql"}` | p99 不持续上升 | diff --git a/docs/ops/go-service-observability.md b/docs/ops/go-service-observability.md index 38e9e9df..c2b09e84 100644 --- a/docs/ops/go-service-observability.md +++ b/docs/ops/go-service-observability.md @@ -47,6 +47,7 @@ curl -fsS http://127.0.0.1:20200/readyz | `vehicle_bridge_batch_pending_messages` | NATS messages fetched by the bridge but not yet written to Kafka and acked. | | `vehicle_bridge_batch_pending_kafka_messages` | Kafka messages prepared for the current bridge batch. | | `vehicle_bridge_batch_duration_ms_histogram` | Bridge batch duration histogram covering Kafka write and NATS ack. Labels: `status`. | +| `vehicle_fast_writer_stage_duration_ms_histogram` | Fast writer stage duration histogram for TDengine, Redis, and NATS ack. Labels: `subject`, `stage`, `status`. | | `vehicle_history_writes_total` | TDengine history writes. Labels: `topic`, `status`. | | `vehicle_history_batch_pending_messages` | Messages fetched by history writer but not yet flushed and committed. | | `vehicle_history_batch_pending_rows` | Parsed raw envelopes waiting in the current TDengine batch. | diff --git a/docs/ops/go-vehicle-ingest-memory.md b/docs/ops/go-vehicle-ingest-memory.md index 6bd3cb4d..2d5f00ae 100644 --- a/docs/ops/go-vehicle-ingest-memory.md +++ b/docs/ops/go-vehicle-ingest-memory.md @@ -409,6 +409,18 @@ vehicle_async_sink_queue_depth{sink} 这些指标是进入带帧率压测前的关键保护栏：如果 `queue_depth` 持续增长、`enqueue_total{status="timeout"}` 增长，或 `vehicle_async_sink_publish_duration_ms_histogram_bucket` 的 p99 持续上升，说明入口 publish 队列或下游 NATS/Kafka 写入已成为瓶颈。 +### NATS fast writer stage histogram + +2026-07-03 已为 NATS fast writer 增加阶段耗时 histogram： + +```text +vehicle_fast_writer_stage_duration_ms_histogram_bucket{subject,stage,status,le} +vehicle_fast_writer_stage_duration_ms_histogram_count{subject,stage,status} +vehicle_fast_writer_stage_duration_ms_histogram_sum{subject,stage,status} +``` + +`stage` 取值包括 `tdengine`、`redis`、`ack`，分别对应快速写 TDengine raw/location、Redis realtime 投影、NATS ack。带帧率压测时如果某个 stage 的 p99 持续上升，可以直接定位 fast path 是存储瓶颈还是 ack/网络瓶颈。 + ### NATS Kafka bridge batch 指标 2026-07-03 已为 NATS -> Kafka bridge 增加 batch pending 和 duration histogram： diff --git a/docs/ops/vehicle-ingest-runbook.md b/docs/ops/vehicle-ingest-runbook.md index d1f9edd6..a91ee44c 100644 --- a/docs/ops/vehicle-ingest-runbook.md +++ b/docs/ops/vehicle-ingest-runbook.md @@ -129,6 +129,7 @@ go run ./cmd/load-sim \ | `vehicle_bridge_nats_consumer_pending` | 持续增长且 `> 10000` | bridge 消费 NATS 的速度跟不上生产速度。 | | `vehicle_bridge_batch_pending_messages` | 持续非 0 或 burst 后不回落 | bridge 已拉取 NATS 消息但尚未完成 Kafka 写入和 NATS ack。 | | `vehicle_bridge_batch_duration_ms_histogram_bucket` | p99 连续 5 分钟上升 | Kafka 写入或 NATS ack 开始变慢，通常会先于 ack-pending 扩大。 | +| `vehicle_fast_writer_stage_duration_ms_histogram_bucket` | 某个 stage 的 p99 连续 5 分钟上升 | NATS 快速写链路在 TDengine、Redis 或 NATS ack 某一阶段变慢。 | | `vehicle_realtime_store_update_duration_ms_histogram_bucket{store="redis"}` | p99 连续 5 分钟上升 | Redis 实时投影变慢，会直接影响 realtime consumer 追平能力。 | | `vehicle_realtime_store_update_duration_ms_histogram_bucket{store="mysql"}` | p99 连续 5 分钟上升 | MySQL 当前态/位置投影变慢，需结合 async queue depth 和 dropped 计数判断。 | | `vehicle_stat_write_duration_ms_histogram_bucket` | p99 连续 5 分钟上升 | MySQL 每日里程统计写入变慢，可能导致 stat Kafka lag 增长。 | diff --git a/go/vehicle-gateway/cmd/nats-fast-writer/main.go b/go/vehicle-gateway/cmd/nats-fast-writer/main.go index a37c1bae..30433987 100644 --- a/go/vehicle-gateway/cmd/nats-fast-writer/main.go +++ b/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 == "" { diff --git a/go/vehicle-gateway/cmd/nats-fast-writer/main_test.go b/go/vehicle-gateway/cmd/nats-fast-writer/main_test.go index 324cf137..e083e0cb 100644 --- a/go/vehicle-gateway/cmd/nats-fast-writer/main_test.go +++ b/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