From dccd0969d8585d27a4dc55e616862d7fda725335 Mon Sep 17 00:00:00 2001 From: richjohnrambo Date: Thu, 1 Oct 2026 16:07:49 +0800 Subject: [PATCH] fix: register cluster kv payloads --- .../IM-单机60%容量压力测试结果-20260929.md | 49 +++++++++++++++++++ loadtest/im-pressure/histogram.go | 1 + loadtest/im-pressure/merge_test.go | 17 +++++++ server/cluster.go | 2 + server/cluster_gob_test.go | 2 + 5 files changed, 71 insertions(+) diff --git a/docs/test/IM-单机60%容量压力测试结果-20260929.md b/docs/test/IM-单机60%容量压力测试结果-20260929.md index 7ddd2e1..e2d5347 100644 --- a/docs/test/IM-单机60%容量压力测试结果-20260929.md +++ b/docs/test/IM-单机60%容量压力测试结果-20260929.md @@ -645,3 +645,52 @@ Run ID：`s900m-p2p-r1-1001`。900 条 WebSocket 连接组成 450 对好友，A/ - `loadtest/im-pressure/results/s900m-p2p-r1-1001/db-verification.json` - `loadtest/im-pressure/results/s900m-p2p-r1-1001/metrics.jsonl` - `loadtest/im-pressure/results/s900m-p2p-r1-1001/server-metrics/` + +## 23. 900 人混合 R4 长 ACK 观测复测 + +Run ID：`s900m-mixed-r4-1001`。负载与 R3 相同：900 条 WebSocket、135 对单聊用户和 224 个群发送者，共发送 1350 条单聊和 448 条群消息。本轮仅将 `command_timeout` 改为 90 秒，并启用 ctrl ACK 晚到台账和服务端 `enqueue/write` 分段指标。 + +| 指标 | 结果 | +|---|---:| +| 就绪连接 | 900 / 900 | +| 发送尝试 / ACK | 1798 / 1798 | +| 明确拒绝 / 结果未知 | 0 / 0 | +| 超过 20 秒的 ACK | 118 | +| 90 秒超时 / 晚到 / 最终未到 | 0 / 0 / 0 | +| ACK P95 / 最大值 | 23425.942ms / 68730.192ms | +| 单聊对端实时投递 | 1350 / 1350 | +| 群聊实时投递 | 403200 / 403200 | +| 实时到达率 / 丢失率 | 100% / 0% | +| 重复 / 乱序 / 断连 | 0 / 0 / 0 | +| 历史回查 | 1798 / 1798 | +| MySQL 精确命中 | 1798 / 1798 | +| MySQL 缺失 / 错配 / 重复 / 额外 | 0 / 0 / 0 / 0 | +| Pod Ready / 重启 | 3 / 3，0 重启 | + +118 条慢 ACK 的精确延迟范围为 20.317 至 68.731 秒，中位数约 27.062 秒，慢样本 P95 约 39.465 秒。两个 agent 分别有 56 和 62 条超过 20 秒的 ACK，但全部在 90 秒内返回。R4 直接证明同负载下存在“20 秒后才到、但未丢失”的 ACK，强力支持 R3 的 47 条超时属于同类晚 ACK，而非服务端拒绝或消息丢失。 + +服务端三个 Pod 的 ctrl ACK 指标共有 1801 个自 Pod 启动后的样本，与本轮 1798 条发送只相差 3 条环境流量： + +| Pod | enqueue 平均 | write 平均 | enqueue/write P95 | +|---|---:|---:|---:| +| im-server-0 | 49.672ms | 50.059ms | 均在 250ms 桶内 | +| im-server-1 | 51.612ms | 52.176ms | 均在 250ms 桶内 | +| im-server-2 | 48.051ms | 48.358ms | 均在 250ms 桶内 | + +ACK 从 WS 队列入队到 socket write 完成只增加约 0.3至0.6ms，而客户端有 118 条超过 20 秒。因此可确认长延迟发生在服务端 socket write 完成之后的 Ingress/LB、公网 TCP/NAT 或压测机接收路径，不在 Topic、持久化、Cluster RPC 或 WS 应用发送队列内。 + +本轮底层共处理 405900 个匹配的 WS data 回调，A/B 的回调队列峰值为 120/149，最大等待仅 9.603/9.199ms，结算时全部排空。Kafka 各 consumer lag 均为 0，未出现 Topic、Cluster proxy 或 WS send queue full；渐进关闭后只有 4 次预期的 ping closed 写错误。 + +报告中 `ack_p95_ms=23425.942` 是基于 1798 条 ACK 原始时间戳的精确值。本轮二进制的 ctrl 直方图上界仅到 10 秒，使 `publish_ctrl_p95_ms` 在 `+Inf` 桶中退化为最大值 68731.141ms，该字段本轮不作为 P95 使用。直方图已增加 20、30、45、60、90 和 120 秒桶及回归测试，下轮会输出正确的长延迟分位桶。 + +服务端日志还发现两次与本轮 Topic 无关的 Cluster Route 失败：`gob: type not registered for interface: types.KVMap`。`types.KVMap` 是命名 map 类型，不会被 `map[string]any` 的 gob 注册覆盖。已补充 `types.KVMap` 和 `[]types.KVMap` 注册，并扩展 Cluster gob 回归测试；该修复需要再发版。 + +本轮 `report.json` 最终 `passed=true`。混合场景的消息正确性、实时到达、顺序、连接稳定性、历史回查和 MySQL 落库均通过；长 ACK 已被定位为 socket write 之后的端到端队头阻塞，不再阻断当前容量验收。 + +新增产物： + +- `loadtest/im-pressure/results/s900m-mixed-r4-1001/report.json` +- `loadtest/im-pressure/results/s900m-mixed-r4-1001/db-verification.json` +- `loadtest/im-pressure/results/s900m-mixed-r4-1001/metrics.jsonl` +- `loadtest/im-pressure/results/s900m-mixed-r4-1001/server-metrics/` +- `loadtest/im-pressure/results/s900m-mixed-r4-1001/im-server-{0,1,2}.log` diff --git a/loadtest/im-pressure/histogram.go b/loadtest/im-pressure/histogram.go index a6c55e1..8a2a84c 100644 --- a/loadtest/im-pressure/histogram.go +++ b/loadtest/im-pressure/histogram.go @@ -10,6 +10,7 @@ var latencyBounds = []time.Duration{ time.Millisecond, 3 * time.Millisecond, 5 * time.Millisecond, 10 * time.Millisecond, 25 * time.Millisecond, 50 * time.Millisecond, 100 * time.Millisecond, 200 * time.Millisecond, 500 * time.Millisecond, time.Second, 2 * time.Second, 5 * time.Second, 10 * time.Second, + 20 * time.Second, 30 * time.Second, 45 * time.Second, 60 * time.Second, 90 * time.Second, 120 * time.Second, } type DurationHistogram struct { diff --git a/loadtest/im-pressure/merge_test.go b/loadtest/im-pressure/merge_test.go index f3ec12b..b59e4e3 100644 --- a/loadtest/im-pressure/merge_test.go +++ b/loadtest/im-pressure/merge_test.go @@ -74,6 +74,23 @@ func TestMergedHistogramP95(t *testing.T) { } } +func TestMergedHistogramP95DoesNotUseMaximumForLongTail(t *testing.T) { + histogram := NewDurationHistogram() + for i := 0; i < 94; i++ { + histogram.Observe(5 * time.Second) + } + for i := 0; i < 5; i++ { + histogram.Observe(25 * time.Second) + } + histogram.Observe(70 * time.Second) + agents := []AgentSummary{{PublishCtrlLatency: histogram.Snapshot()}} + if got := mergedHistogramP95(agents, func(summary AgentSummary) HistogramSnapshot { + return summary.PublishCtrlLatency + }); got != 30000 { + t.Fatalf("p95=%v want=30000", got) + } +} + func TestMergedAckP95UsesExactAcceptedTimestamps(t *testing.T) { base := time.Date(2026, 9, 27, 8, 0, 0, 0, time.UTC) agents := []AgentSummary{{ diff --git a/server/cluster.go b/server/cluster.go index 56fffd2..bf14e52 100644 --- a/server/cluster.go +++ b/server/cluster.go @@ -1217,6 +1217,8 @@ func registerClusterGobTypes() { gob.Register([]any{}) gob.Register([]map[string]any{}) gob.Register(map[string]any{}) + gob.Register(types.KVMap{}) + gob.Register([]types.KVMap{}) gob.Register(map[string]int{}) gob.Register(map[string]string{}) gob.Register(MsgAccessMode{}) diff --git a/server/cluster_gob_test.go b/server/cluster_gob_test.go index 4b0f3bb..8ef5ed9 100644 --- a/server/cluster_gob_test.go +++ b/server/cluster_gob_test.go @@ -29,6 +29,8 @@ func TestClusterGobRegistersSystemMessagePayloadTypes(t *testing.T) { "text": "成员加入了群聊", "template": "group_member_joined", "items": []map[string]any{{"type": "member", "id": "usr123"}}, + "action": types.KVMap{"type": "group_profile", "target_id": "grpTest"}, + "rows": []types.KVMap{{"type": "member", "id": "usr123"}}, "actors": []imSystemMessageActor{{ UserID: "usr123", Click: map[string]any{"type": "user_profile", "target_id": "usr123"},