178 lines
9.6 KiB
Markdown
178 lines
9.6 KiB
Markdown
# IM 单聊压测 Pod 日志根因分析与改进方案
|
||
|
||
日期：2026-09-27
|
||
|
||
## 1. 结论
|
||
|
||
`p2p-20260927-01` 不通过的主因已定位为 **Tinode 原生 Cluster 转发能力在突发流量下耗尽**，不是 Pod 崩溃、Pod 重启或集群节点断开。
|
||
|
||
直接故障链路：
|
||
|
||
1. 客户端连接所在 Pod 不是 P2P Topic 的 master 时，请求进入 proxy-to-master 转发。
|
||
2. 当前每个远端节点只有 1 个同步 RPC 发送协程，队列容量只有 64。
|
||
3. 队列满后仅等待 20ms，随即返回 `cluster: load exceeded`。
|
||
4. Topic proxy 将该错误转换为 WebSocket `502 cluster unreachable`。
|
||
5. 反向投递进入 `hub.routeSrv` 时，4096 容量队列也出现满载；当前 RPC 调用方忽略 `rejected` 结果，存在静默丢弃路径。
|
||
|
||
因此，本轮 `40.665%` 的发送失败率是 Cluster 内部排队与串行 RPC 的结果。Redis/Kafka 没有参与这条 Topic proxy-to-master 请求路径，不是本次故障点。
|
||
|
||
## 2. 压测结果对照
|
||
|
||
| 指标 | 结果 |
|
||
|---|---:|
|
||
| WS Ready | 2000/2000 |
|
||
| Publish 尝试 | 20000 |
|
||
| 服务端 ACK | 11867 |
|
||
| 拒绝或超时 | 8133 |
|
||
| ACK 成功率 | 59.335% |
|
||
| ACK 后应到达 | 11867 |
|
||
| ACK 后实际到达 | 11859 |
|
||
| 实时丢失 | 8 |
|
||
| ACK 后到达率 | 99.9326% |
|
||
| 重复/乱序/断连 | 0 / 2 / 1 |
|
||
| ACK 平均/最大延迟 | 3.079s / 18.715s |
|
||
| 投递平均/最大延迟 | 4.178s / 21.741s |
|
||
|
||
8 条丢失全部集中在 `B -> A` 用户序号 0959，与 A 机记录到的 1 次 WS 断连同时出现。
|
||
|
||
## 3. Kubernetes 现状
|
||
|
||
| 项目 | 实际值 |
|
||
|---|---|
|
||
| Namespace | `im-server-system` |
|
||
| Workload | `StatefulSet/im-server` |
|
||
| 副本 | 3/3 Ready |
|
||
| Pod | `im-server-0/1/2` |
|
||
| 节点分布 | 3 个 Pod 在 3 个不同 K8s Node |
|
||
| 重启 | 全部为 0 |
|
||
| 镜像 | 3 Pod 使用相同 digest |
|
||
| CPU request/limit | `100m / 500m` |
|
||
| Memory request/limit | `128Mi / 256Mi` |
|
||
| Cluster 端口 | 12000 |
|
||
|
||
Pod 没有 OOM/Kill，内存 cgroup 没有 `oom` 或 `oom_kill`。未观察到集群 TCP 断开、`node not connected`、panic 或 fatal。
|
||
|
||
## 4. Pod 日志证据
|
||
|
||
压测发送窗口：2026-09-26 18:02:45Z 至 18:03:24Z（北京时间 02:02:45 至 02:03:24）。
|
||
|
||
`im-server-0` 的可用完整窗口日志中：
|
||
|
||
| 日志 | 次数 |
|
||
|---|---:|
|
||
| `route broadcast request from proxy to master failed - cluster: load exceeded` | 2259 |
|
||
| `cluster Route: server busy` | 3889 |
|
||
| `cluster: node ... not connected` | 0 |
|
||
| cluster RPC connection error | 0 |
|
||
| panic/fatal | 0 |
|
||
|
||
`im-server-2` 当前保留的日志从 18:03:19Z 才开始，仅最后约 5 秒已有 496 次 `cluster Route: server busy`。`im-server-1` 当前日志从 18:15:47Z 开始，本次发送窗口已被轮转覆盖。
|
||
|
||
因此 2259 和 4385（3889+496）都是 **可见日志下界**，不是整个集群的全量。这也是日志量与客户端 8133 次拒绝/超时不完全相等的主要原因之一。
|
||
|
||
错误从发送开始后立即出现，`im-server-0` 前 10 秒每秒约有 180-226 条 Cluster 过载日志，说明它不是某个后台定时任务引起，而是与本轮 publish 突发直接相关。
|
||
|
||
## 5. 代码级根因
|
||
|
||
### 5.1 proxy-to-master 队列过小
|
||
|
||
`server/cluster.go` 将 `clusterProxyToMasterBuffer` 固定为 64，`clusterP2MTimeout` 固定为 20ms。3 节点时 `len(c.nodes)==2`，扩容逻辑不生效，所以每个远端 peer 实际只有 64 个缓冲位。
|
||
|
||
队列满后，`proxyToMasterAsync` 在 20ms 后返回 `cluster: load exceeded`。`topic_proxy.go` 随即给客户端返回 502。日志与代码路径一致。
|
||
|
||
### 5.2 每个 peer 只有一个同步 RPC worker
|
||
|
||
`p2mSenderLoop` 只启动一次，循环内调用同步 `endpoint.Call`。该 peer 上任何一个较慢的 TopicMaster RPC 都会阻塞后续所有 Topic。在 1000 对用户同时 publish 时，64 队列很快被填满。
|
||
|
||
### 5.3 接收侧有静默丢弃路径
|
||
|
||
`Cluster.Route` 在 `globals.hub.routeSrv` 满时设置 `rejected=true`并打印 `cluster Route: server busy`。但 `ClusterNode.route` 只检查 RPC error，传入的 bool 命名为 `unused`，没有检查被远端拒绝的结果。
|
||
|
||
这意味着发送方可能认为 RPC 成功，但接收方已经因队列满而丢弃消息。本轮 8 条 ACK 后实时丢失与此风险方向一致，但因全量日志已部分轮转，无法将每一条 Client MID 与具体 server-busy 日志逐条对齐。
|
||
|
||
### 5.4 资源限制会放大排队
|
||
|
||
每个 Pod 的 CPU limit 只有 500m，同时承担 1000 量级 WS、Topic goroutine、net/rpc、MySQL 持久化和实时投递。当前 cgroup 累计存在 CPU throttling，但没有压测时间窗的 Prometheus 历史样本，所以只能将 CPU 限制定义为高概率放大因素，不将其单独认定为根因。
|
||
|
||
## 6. 次要问题
|
||
|
||
### 6.1 403 permission denied
|
||
|
||
两台 agent 保留的前 1000 条错误中，A 有 11 条、B 有 24 条 403。多个相同用户序号在 A/B 两侧同时出现，例如 0082、0175、0304、0401、0773。这表明少量 P2P Topic 的发布权限或好友/Topic 初始化状态不一致，与 Cluster 过载是独立问题。
|
||
|
||
### 6.2 历史回查程序串行阻塞
|
||
|
||
压测程序对 1000 个 Topic 串行调用 history GET，每次控制应答最长等 20 秒，导致收尾耗时达 13-19 分钟。`history_found=0` 只能说本轮回查无效，不能据此认定 MySQL 丢数据。
|
||
|
||
### 6.3 日志保留不足
|
||
|
||
压测后不到 20 分钟，`im-server-1` 和 `im-server-2` 的关键窗口已部分或全部被容器日志轮转覆盖。没有集中日志时，无法完整重建三 Pod 时间线。
|
||
|
||
## 7. 改进方案
|
||
|
||
### P0：修复 Cluster 转发实现
|
||
|
||
1. 将 cluster buffer、enqueue timeout、worker 数改为可配置项，不再使用 64/20ms 硬编码。
|
||
2. 每个 peer 使用有界并发 RPC worker pool。为保证同一 Topic 的顺序，应按 `tenant_id + topic` 做固定分片，同一 Topic 始终进入同一 worker。
|
||
3. 首轮建议值：每 peer 16 个 worker、总 buffer 4096、enqueue timeout 200-500ms。该数值必须通过阶梯压测定标，不应作为无上限扩容。
|
||
4. 修复 `ClusterNode.route`：检查远端 `rejected` 并返回明确 overload error，禁止静默成功。
|
||
5. 对已持久化的 ServerComMessage 建立有界重试（例如 3 次指数退避）。超过重试上限要记录可检索的 tenant/topic/seq/target pod，并由客户端重连后历史同步补齐。
|
||
6. 将 overload 与 node unreachable 分开：队列满返回 503/`cluster overloaded`，只有节点断连才返回 502/`cluster unreachable`。
|
||
|
||
### P0：调整部署资源与入口
|
||
|
||
1. 测试环境首轮将每 Pod request 调整为 `cpu: 1, memory: 512Mi`，limit 调整为 `cpu: 2, memory: 1Gi`；运行阶梯压测后再根据 P95 调整。
|
||
2. 核对客户端 Service/Ingress：`sessionAffinity: None`，WebSocket upstream 不使用 `ip_hash`，建议 `least_conn` 或等价的长连接均衡策略。
|
||
3. 在压测开始前记录每 Pod `ws_connections_active`，单 Pod 连接数不得超过平均值的 1.3 倍。
|
||
4. readiness 增加 `LiveClusterNodes == TotalClusterNodes-1` 和 cluster queue 长时间高水位检查，但不应因瞬时高水位造成 Pod 反复摘除。
|
||
|
||
### P1：增加可观测性
|
||
|
||
新增以下 Prometheus 指标，必须带 `pod` 和 `peer` 维度，Topic 只记 hash：
|
||
|
||
- `im_cluster_p2m_queue_length/capacity`
|
||
- `im_cluster_p2m_enqueue_total{result=ok|timeout}`
|
||
- `im_cluster_rpc_inflight`
|
||
- `im_cluster_rpc_duration_seconds`
|
||
- `im_cluster_route_total{result=ok|hub_full|peer_rejected|disconnected}`
|
||
- `im_cluster_proxy_response_total{result=ok|channel_full|unknown_topic}`
|
||
- `im_ws_connections_active{pod}`
|
||
- `im_message_persist_duration_seconds`
|
||
|
||
告警建议：
|
||
|
||
- queue 使用率连续 30s 超过 70%：预警；超过 90%：严重。
|
||
- `enqueue timeout` 或 `hub_full` 1 分钟内大于 0：严重。
|
||
- `LiveClusterNodes` 低于期望值：严重。
|
||
- WS 连接不均衡比超过 1.3：预警。
|
||
|
||
日志应接入 Loki/ELK 等集中系统，至少保留 7 天。限速相同 overload 日志，用计数指标补全被限速的数量，避免大量重复日志反过来抢占 CPU 和 IO。
|
||
|
||
### P1：修复压测程序
|
||
|
||
1. history 回查改为 32-64 有界并发，总收尾超时不超过 3 分钟。
|
||
2. 分开统计 `publish_502`、`publish_503`、`publish_403`、`publish_ctrl_timeout`、`socket_error`，不再只保留前 1000 条文本错误。
|
||
3. 对所有 1000 对用户做发布权限预检，修复 403 后再开始正式计时。
|
||
4. 在两台压测机启动前、发送中、收尾后自动抓取 Pod/Redis/Kafka/MySQL 指标快照。
|
||
5. 历史落库验证增加 MySQL 直查作为独立通道，以 `tenant_id + topic + client_mid/seq` 分批校验。
|
||
|
||
## 8. 复测顺序与通过门槛
|
||
|
||
1. 200 对、500 对、1000 对分三档，每档至少跑 3 轮。
|
||
2. 每档同时执行“均匀爬坡”和“同时突发”两种模式。
|
||
3. 最终 1000 对场景通过门槛：
|
||
- publish ACK 成功率不低于 99.99%。
|
||
- ACK 后对端到达率为 100%，重复为 0。
|
||
- Cluster enqueue timeout、hub full、peer rejected 均为 0。
|
||
- ACK P95 < 500ms，对端投递 P95 < 1s。
|
||
- MySQL 落库校验 100%。
|
||
- 单 Pod CPU P95 < 70%，内存 P95 < limit 的 70%，无持续 CPU throttling。
|
||
|
||
## 9. 本次调查限制
|
||
|
||
- 调试 ServiceAccount 可读 Pod/StatefulSet/log，但不可读 Service/Endpoint 和 metrics-server 历史数据。
|
||
- `im-server-1/2` 的压测窗口日志已部分轮转，日志次数只能作为下界。
|
||
- 未获得当时的 CPU、内存、网络、MySQL、Redis、Kafka 时序监控，不对这些组件的历史利用率做无证据推断。
|
||
|
||
即使存在上述限制，`cluster: load exceeded` 与 `cluster Route: server busy` 已与硬编码队列/超时路径完整对应，足以确认 Cluster 转发过载是本轮的主故障。
|