im_server/docs/test/IM-单聊压测Pod日志根因分析与改进方案-20260927.md

# IM 单聊压测 Pod 日志根因分析与改进方案

日期：2026-09-27

## 1. 结论

`p2p-20260927-01` 暴露了两个相互独立的 P0 故障：

1. **Tinode 原生 Cluster 转发能力在突发流量下耗尽**，造成 8133 次 publish 拒绝或超时。
2. **Kafka 异步落库写入 Snowflake ID 时与 MySQL 32 位 `INT` 字段不兼容**，造成客户端已 ACK 的消息没有落入 MySQL。

两者都不是 Pod 崩溃、Pod 重启或集群节点断开导致。实时投递接近成功不代表持久化成功，本轮必须同时判定 Cluster 投递和 MySQL 落库不通过。

直接故障链路：

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 请求路径，不是发送失败的故障点；但 Kafka 消费到 MySQL 的异步持久化链路另有独立故障。

## 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 断连同时出现。

### 2.1 MySQL 直接核验

2026-09-27 通过 Pod 当前的只读数据库连接，对租户 `allrich`（`tenant_id=8`）进行了两层核验：

| 核验项 | 结果 |
|---|---:|
| 客户端收到 ACK | 11867 |
| `im_008_messages` 按本次 `client_msg_id` 前缀命中 | 0 |
| `im_008_messages` 按 `content.run_id=p2p-20260927-01` 命中 | 0 |
| `im_messages` 按 `content.run_id=p2p-20260927-01` 命中 | 0 |
| ACK 消息精确匹配 `client_mid + topic + seq` | 0/11867 |
| 本轮已生成 Kafka 死信（核验时点） | 27 |
| 死信错误 | `Error 1264: Out of range value for column 'id'` |

结论：修复前，本轮 ACK 消息的 **MySQL 落库率为 0%**。27 是首次核验时已完成重试并转入死信的数量，不是最终总数；当时其余消息仍位于 Kafka backlog 或处理中。

### 2.2 修复执行与数据恢复结果

2026-09-27 已在本地和测试环境执行 `docs/sql/IM-消息表Snowflake-ID-BIGINT修复SQL.sql` 对应迁移：

- 本地 `meeting_im.im_messages.id` 已由 `INT` 改为 `BIGINT NOT NULL AUTO_INCREMENT`。
- 测试环境 `meeting_im.im_messages` 以及 `im_001_messages` 至 `im_009_messages` 共 10 张表已全部改为 `BIGINT NOT NULL AUTO_INCREMENT`，后置校验异常数为 0。
- 修复后 Kafka backlog 自动恢复落库 11835 条；本轮已有 32 条消息进入死信，通过系统 `kafka.dead_letter.replay` 命令完成重放。

使用原始 ACK ledger 对恢复后的数据库逐条校验：

| 核验项 | 最终结果 |
|---|---:|
| ACK ledger | 11867 |
| 数据库本轮消息行 | 11867 |
| `client_mid + topic + seq` 精确匹配 | 11867 |
| 缺失 | 0 |
| 错配 | 0 |
| 重复 | 0 |
| 拒绝/超时请求意外落库 | 0/8133 |

因此本轮已确认 ACK 消息最终 100% 落库。这里的最终结果是执行字段迁移、等待 Kafka backlog 排空并重放死信后的恢复结果，不代表故障发生时的异步持久化链路正常。

## 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 限制定义为高概率放大因素，不将其单独认定为根因。

### 5.5 Kafka 异步落库主键类型不兼容

当前代码在 Kafka 入队前通过 `store.Store.GetUid()` 生成 Snowflake 消息 ID。消费者批量落库时，`TenantMessageSaveBatch` 显式把该 ID 写入 `im_008_messages.id`。

线上实际字段类型为：

| 表 | `id` 类型 |
|---|---|
| `im_messages` | `INT` |
| `im_008_messages` | `INT` |

Snowflake ID 超过有符号 32 位 `INT` 上限，批量插入立即报 1264。代码降级为逐条处理时仍调用同一个批量写入方法，因此不会绕过该错误；达到重试上限后消息进入 `im_kafka_dead_letters`。与此同时，WebSocket 202/ACK 在 Kafka publish 成功后就返回，因而客户端会观察到“ACK 成功、实时广播成功、历史和数据库没有消息”。

这是数据库 DDL 与当前异步持久化代码契约不一致。仓库初始化 SQL 也仍把 `im_messages.id` 定义为 `INT`，因此新环境同样会复现。

## 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 丢数据；本报告新增的 MySQL 直查与 Kafka 死信证据已经独立确认落库失败。

### 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：恢复 Kafka 消息持久化

1. 暂停新的压力流量，避免继续扩大 Kafka backlog 和死信数量。
2. 审核并执行 `docs/sql/IM-消息表Snowflake-ID-BIGINT修复SQL.sql`，把基础表及所有 `im_NNN_messages.id` 改为 `BIGINT NOT NULL AUTO_INCREMENT`。保留 `AUTO_INCREMENT` 是为了兼容 Kafka 关闭时不显式传 ID 的同步写入路径。
3. 变更后先发 1 条带唯一 `client_mid` 的探针消息，确认 Kafka 消费、MySQL 行、Topic seq 和历史查询一致。
4. 再通过现有死信管理接口重放本轮 `message.persist.p2p` 死信；Kafka 中尚未提交的 backlog 会由消费者继续处理。不要直接删除死信或重置 offset。
5. 以本轮 11867 个 ACK ledger 做最终精确核对，要求 `client_mid + topic + seq` 为 11867/11867，重复为 0。
6. 增加启动前 schema contract 检查：Kafka 持久化启用时，若私聊消息基础表或任何租户分表的 `id` 不是 BIGINT，Pod readiness 必须失败并输出明确的表名和字段类型。
7. 增加 `kafka_message_persist_total{result=batch_ok|single_ok|retry|dead}`、消费 lag、死信累计量和最老 backlog age 告警。客户端 ACK 语义应明确为“Kafka 已接收（pending）”，服务端另行提供最终持久化状态；若产品要求 ACK 等于已落库，则必须改为同步确认或增加持久化回执。

### 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%。
   - Kafka consumer lag 在发送停止后 60 秒内归零，死信新增为 0。
   - 单 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 时序监控，不对这些组件的历史利用率做无证据推断。
- Kafka backlog 的精确条数无法通过当前调试 ServiceAccount 直接读取；死信 27 条只代表核验时已经完成失败重试的部分。

即使存在上述限制，现有证据已足以分别确认 Cluster 转发过载和 Kafka 持久化主键溢出。修复并完成死信/backlog 恢复前，本轮数据不能视为已持久化。

## 10. P0/P1 实施状态

2026-09-27 已完成代码与发布配置改造：

- Cluster 使用按 `tenant_id + topic` 固定分片的 16 worker、每 peer 总队列 4096、入队超时 300ms；远端 `hub_full` 有 3 次指数退避重试，过载返回 503，节点断连保持 502。
- TopicMaster 的客户端 publish 接收队列满时会通过 multiplex session 回 503，不再只记录日志后等待客户端超时；同类过载日志每秒限速，完整次数由指标保留。
- Kafka 启用时，启动阶段校验基础私聊表及所有活动租户私聊分表的 `id` 必须为 `BIGINT NOT NULL AUTO_INCREMENT`，不满足时进程不会进入 Ready。
- 增加 Cluster 队列/RPC/路由、WebSocket 连接、Kafka 持久化结果/lag/backlog age/死信及持久化耗时指标和 PrometheusRule 告警。
- `/healthz` 检查全部 Cluster peer，并仅在队列超过 90% 持续 30 秒时摘除 readiness；新增 `/livez` 供 liveness 使用，避免 Cluster 短暂异常触发 Pod 重启。
- 测试环境发布流水线应用 `request=1C/512Mi`、`limit=2C/1Gi`，设置 Cluster 参数、Service `sessionAffinity=None`，并在存在 `Ingress/im-server` 时设置 NGINX `least_conn`。
- 压测程序增加全量 P2P 预检、48 worker 历史回查、3 分钟总超时、publish 错误分类、指标快照阶段标记、P95/ACK 成功率门禁及 MySQL 独立精确核验。

当前调试 kubeconfig 对 StatefulSet/Service/Ingress 没有 patch 权限，因此现存 Pod 资源尚未被本地会话直接修改；以上部署项会在新提交触发有权限的 Gitea deploy runner 后生效。生效后必须按第 8 节执行 200/500/1000 对阶梯复测，不能用单元测试替代容量验收。