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 对阶梯复测，不能用单元测试替代容量验收。

## 11. 200 对阶梯复测结果

Run ID：`p2p-200-20260927-01`，A/B 两台压测机各模拟 200 个用户，共 200 对、400 条 WebSocket 连接。

| 指标 | 结果 |
|---|---:|
| WS Ready | 400/400 |
| Publish 尝试 | 4000 |
| 服务端 ACK | 3890 |
| 403 拒绝 | 110 |
| 502 / 503 / ctrl timeout / socket error | 0 / 0 / 0 / 0 |
| ACK 后应到达 / 实际到达 | 3890 / 3890 |
| ACK 后到达率 | 100% |
| 实时丢失 / 重复 / 乱序 / 断连 | 0 / 0 / 0 / 0 |
| Kafka P2P `batch_ok` | 3890 |
| Kafka consumer lag / backlog age | 0 / 0 |
| MySQL 精确匹配 | 3890/3890 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 |

本轮没有再出现 `cluster: load exceeded`、`server busy`、502 或 503，说明 Cluster P0 改造在 200 对档位已生效。Kafka 消费指标和 MySQL 对 ACK ledger 的独立精确查询均确认 3890 条消息已全部落库。

压测报告当时的 `history_found=2213`、`persistence_lost=1677` 不是真实落库丢失。旧实现首轮查询后仅等待 2 秒，再进行两次 2 秒重试，并未持续到配置的 3 分钟截止时间。已改为在 `history_timeout` 内持续重试，并按 Topic 合并缺失区间查询，避免过早判定和大量单条请求。

### 11.1 403 根因与修复

110 次 403 稳定集中在用户序号 `0018`、`0043`、`0065`、`0082`、`0175`、`0183` 的 6 个 P2P Topic，与 Cluster 转发无关。`EnsureP2P` 已将 MySQL 中双方订阅修复为 `JRWPA`，但已加载 Topic 的 `perUser` 仍保留旧权限，因此预检通过后 WebSocket publish 仍被内存态拒绝。

已增加两层修复：

1. HTTP `EnsureP2P` 成功后向 Topic master 发布内部权限刷新事件，原生 Cluster 由 `routeSrv` 路由，非原生多 Pod 模式由 Redis realtime fanout 路由。
2. P2P publish 发现内存态无写权限时，先从 MySQL 重载该用户订阅再判定，作为刷新事件延迟或丢失时的自愈保障。数据库仍无写权限时依然返回 403。

### 11.2 当前未达标项

- ACK P95 和到达 P95 均落在 2 秒直方图上界，未达 500ms / 1s 门槛。
- ArgoCD 已将 StatefulSet 资源回滚为 `request 100m/128Mi`、`limit 500m/256Mi`，且 liveness 仍使用 `/healthz`。压测期间存在 CPU throttling 累计，部署配置必须在 GitOps 声明源中固化，否则应用后仍会被回滚。
- 403 修复发布后应重跑 200 对；只有 ACK 成功率、实时到达率、MySQL 精确落库均达标，才进入 500 对档位。

## 12. 200 对第三轮复测结果

Run ID：`p2p-200-20260927-03`。压测前修复了压测工具复用固定 `Idempotency-Key` 而跳过好友关系校验的问题，并重新核对、修复 200 对测试账号。

| 指标 | 结果 |
|---|---:|
| WS Ready | 400/400 |
| Publish 尝试 / ACK | 4000 / 4000 |
| Publish 拒绝 / 403 / 502 / 503 | 0 / 0 / 0 / 0 |
| ACK 后应到达 / 实际到达 | 4000 / 4000 |
| 实时到达率 | 100% |
| 历史查询 | 4000/4000 |
| MySQL 精确匹配 | 4000/4000 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 |
| 丢失 / 重复 / 断连 | 0 / 0 / 0 |
| 乱序 | 1 |
| Cluster 队列采样最大值 | 0 |
| Kafka 峰值 lag / 最旧 backlog age / 最终 lag | 3028 / 92.624s / 0 |

结论：跨 Pod 发送、ACK 后实时投递、Kafka 最终消费和 MySQL 落库的数据正确性已通过 200 对验证。结果报告仍为不通过，原因是 B 端记录 1 次单连接 Topic seq 回退，以及 ACK P95 和投递 P95 均落入 1-2s 区间。

资源采样显示，三个 Pod 峰值内存低于 94MiB，但 Pod 0/1/2 在本轮窗口内的 CPU throttled 增量约为 7.62s / 0.78s / 8.51s。实际 StatefulSet 仍是 `request 100m/128Mi`、`limit 500m/256Mi`，且 liveness 仍是 `/healthz`。因此延迟和 Kafka 追平速度尚不能作为扩容到 500 对的验收基线。

已增加 `deploy/argocd/im-server-test/statefulset-performance-patch.yaml`，要求 ArgoCD 声明源固化 `request 1C/512Mi`、`limit 2C/1Gi`和 `/livez` liveness。部署流水线改为等待 ArgoCD 回写后严格校验，如果再被回滚则直接失败。压测工具保留乱序为失败门禁，并新增最多 100 条 `receiver/topic_hash/previous_seq/current_seq/client_mid` 明细，用于下轮精确定位。

## 13. GitOps 资源生效后的第四轮复测

Run ID：`p2p-200-20260927-04`。ArgoCD Application `im-server-test` 的真实配置仓库已固化 `request 1C/512Mi`、`limit 2C/1Gi` 和 `/livez`，三个 Pod 完成滚动后均为 Ready、零重启。

| 指标 | 结果 |
|---|---:|
| WS Ready | 400/400 |
| Publish 尝试 / ACK | 4000 / 4000 |
| Publish 拒绝 / 403 / 502 / 503 | 0 / 0 / 0 / 0 |
| ACK 后应到达 / 实际到达 | 4000 / 4000 |
| 实时丢失 / 重复 / 乱序 / 断连 | 0 / 0 / 0 / 0 |
| 历史查询 | 4000/4000 |
| MySQL 精确匹配 | 4000/4000 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 |
| 精确 ACK P50 / P95 / P99 / Max | 368.189 / 566.683 / 725.654 / 1600.975 ms |
| 投递 P95 直方图上界 | 1000 ms |
| Cluster 队列采样最大值 | 0 |
| Kafka message persist 峰值 lag / 归零耗时 | 2946 / 发送结束后 113s |
| Pod 0/1/2 CPU throttled 增量 | 0 / 0 / 0 usec |
| Pod 0/1/2 峰值内存 | 87.86 / 80.80 / 85.18 MiB |

结论：消息正确性全部通过，第三轮出现的 1 条 seq 回退没有复现。资源扩容完全消除了本轮 CPU throttling，证明旧的 500m CPU limit 是延迟放大因素之一；精确 ACK P95 从第三轮的 1006.288ms 降至 566.683ms，下降约 43.7%，但仍比 500ms 门槛高约 13.3%，因此报告只因 ACK 延迟门禁判定失败。

Kafka `im-server.message_persist` lag 在发送后峰值为 2946，并在发送结束后约 113 秒归零，超过 60 秒目标。历史 API 和 MySQL 最终均确认 4000 条完整落库，说明这是落库延迟而不是消息丢失。进入 500 对测试前，应优先检查 message persist consumer 的批量写入、worker/partition 并行度和 MySQL 写入耗时。

连接集中关闭期间，三个 Pod 分别记录 10、14、22 次 `failed to close login audit ... Deadlock found`，共 46 次。该问题未影响消息表，但会导致登录审计结束状态不完整。登录审计关闭更新应增加 MySQL 1213/1205 有界重试，并检查更新条件和索引以缩小锁范围。

## 14. 持久化并行与审计死锁修复后的第五轮复测

Run ID：`p2p-200-20260927-05`。本轮已将 `im.message.persist` 和 `im.group.message.persist` 固化为 3 分区、3 副本；同一 Topic 继续作为 Kafka key，保证会话内顺序。服务端同时按 batch 内最大 Seq 合并 Topic 和发送者已读位点更新，并为登录审计关闭增加复合索引和 MySQL 死锁重试。

| 指标 | 结果 |
|---|---:|
| WS Ready | 400/400 |
| Publish 尝试 / ACK | 4000 / 4000 |
| ACK 后应到达 / 实际到达 | 4000 / 4000 |
| 丢失 / 重复 / 乱序 / 断连 | 0 / 0 / 0 / 0 |
| 历史查询 / MySQL 精确匹配 | 4000/4000 / 4000/4000 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 |
| 总体精确 ACK P50 / P95 / P99 / Max | 375.314 / 547.516 / 670.317 / 2845.347 ms |
| A 机精确 ACK P95 | 408.155 ms |
| B 机精确 ACK P95 | 594.533 ms |
| Pod 0/1/2 Kafka 峰值 lag | 676 / 251 / 143 |
| 最慢 Kafka 分区归零时间 | 发送结束后约 52.5s |
| Cluster 队列峰值 / CPU throttled 增量 | 0 / 三 Pod 均为 0 |
| 登录审计关闭死锁 | 三 Pod 均为 0 |
| Kafka batch failure / Pod 重启 | 0 / 0 |

结论：三分区已由三个 Pod 实际并行消费，单 Pod 峰值 lag 从第四轮的 2946 降至 676，最慢消费者在 60 秒门槛内归零。消息正确性、最终落库、会话内顺序、CPU 限流和登录审计死锁均通过。

报告仍因 ACK P95 门禁显示失败。直方图只能给出 1000ms 上界，按 4000 条 ACK 原始时间戳和 nearest-rank 口径计算的实际 P95 为 547.516ms。A 机已经低于 500ms，而 B 机为 594.533ms，且 B 机存在 2.845s 最大长尾；两台机器使用相同公共入口和相同服务端版本，因此继续修改服务端前，应先采集 B 机到 `api.118im.com` 的 DNS、TCP、TLS、WebSocket RTT 与时钟偏差，并使用定向 Pod 入口做 A/B 对照，区分公网链路长尾和服务端处理耗时。

## 15. 500 对第一轮容量测试

Run ID：`p2p-500-20260927-01`。A/B 各建立 500 条 WebSocket，共 500 对、1000 条连接和 10000 次 Publish。正式发压前补齐了第 201–500 对中缺失的 9 对好友权限，两端预检和 Ready 均通过。

| 指标 | 结果 |
|---|---:|
| WS Ready | 1000/1000 |
| Publish 尝试 / ACK | 10000 / 9946 |
| Publish 失败 | 54（44 条服务端 500/other，10 条 socket error） |
| Publish 成功率 | 99.46% |
| ACK 后应到达 / 实际到达 | 9946 / 9936 |
| 实时丢失 / 重复 / 乱序 / 断连 | 10 / 0 / 0 / 1 |
| 实时到达率 | 99.8995% |
| 总体精确 ACK P95 / Max | 2429.954 / 3636.045 ms |
| 压测期历史回查 | 8580/9946 |
| Kafka 完全排空后 MySQL 精确匹配 | 9946/9946 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 |
| Pod 0/1/2 Kafka 峰值 lag | 2490 / 3234 / 2745 |
| Kafka 归零时间 | 发送结束后约 4 分钟 |
| Pod 0/1/2 峰值内存 | 148.1 / 130.5 / 122.4 MiB |
| Pod 0/1/2 CPU throttled 增量 | 0 / 0 / 0 |
| Pod 重启 | 0 |

本轮不通过，不得升级到 1000 对。根因是 MySQL 连接容量与 IM Server 连接池上限不匹配：

- MySQL `max_connections=170`，本轮 `Max_used_connections=172`，`Connection_errors_max_connections=27`。
- IM Server 每 Pod `max_open_conns=64`，3 个 Pod 的理论连接池上限已达 192，还未计入 admin server、其他服务和运维连接。
- 本轮 Pod 0/1 分别记录 153/19 次 `Error 1040: Too many connections`，包括 50 次 `failed to save message`和 44 次 P2P 关系检查失败；这些错误与 44 条服务端 500 同时出现。
- A 机用户 190 的 WebSocket 断开，产生 10 次 socket error，并导致对端已 ACK 的 10 条消息未能实时投递到该连接。
- 压测结束阶段 Pod 2 记录 282 次群 Topic broadcast queue full，发生在大量会话同时清理期，需要与消息发送链路分开处理。

压测阶段的 `history_found=8580`不是最终丢库：历史回查结束时 Kafka 仍在积压，等 lag 归零后从 Pod 内使用 ACK ledger 独立查询 `im_008_messages`，9946 条全部精确匹配。因此当前是“已接受消息最终零丢失，但持久化延迟超标”。

下一轮 500 对复测前必须先完成：

1. 统一规划 MySQL 全局连接预算，覆盖 IM Server、admin server 及其他共库服务；单个服务的连接池上限不能独立设置到总库容量。
2. 修正 IM Server 每 Pod 的 `max_open_conns/max_idle_conns`，或在验证 MySQL CPU、内存、线程和 PXC 限制后提高 `max_connections`；必须保留至少 20% 全局余量。
3. 压测中增加 DB pool `OpenConnections/InUse/Idle/WaitCount/WaitDuration`和 MySQL `Threads_connected/Threads_running/Max_used_connections/Connection_errors_max_connections` 指标。
4. 复测要求 Publish ACK 10000/10000、实时丢失和断连为 0、Kafka 60 秒内归零、MySQL 1040 和清理期 queue full 为 0，然后才能进入 1000 对。

### 15.1 为什么 Kafka 可以积压，但本轮仍会报错

Kafka 积压只能保护“已经成功写入 Kafka”的消息。正常情况下，consumer 落库变慢只会使 lag 上升，消息会在 Kafka 中等待，不应导致 Publish 报错。本轮的 54 条失败发生在 Kafka 之前：

1. 普通文本消息先同步查询青少年模式设置，但当前规则无论查询结果都允许消息继续进入内容审核。
2. P2P 发布在写 Kafka 前调用 `CanSendP2P`，旧实现即使 Redis 已命中好友关系，仍会读取 MySQL 用户和好友记录。
3. 入口校验、Kafka consumer、历史查询和登录审计共用 MySQL 连接预算。连接耗尽后，入口校验直接返回 500，这些消息没有进入 Kafka，因此无法通过“后续慢慢消费”恢复。

### 15.2 IM 侧改造

2026-09-27 已完成以下修复：

- 普通消息不再读取青少年模式表；通话的夜间禁用规则仍保留数据库查询。
- P2P 热路径先查双向黑名单缓存，再使用好友正缓存；缓存未命中或 Redis 异常时才回源 MySQL。新增拉黑会同时清理双向好友正缓存，避免安全状态陈旧。
- `meeting_im` 每 Pod 连接池设为 `max_open=24/max_idle=8`，`hotgo` 注册表库独立设为 `max_open=4/max_idle=2`。3 个 Pod 的 IM 理论总上限由 384 降为 84；结合 Workbench 30、Manager 20 的上限，整套服务理论上限为 134，在当前 MySQL 170 连接上限下保留 36 条全局余量。
- 连接池参数改为环境变量，并同时固化到应用仓库及 ArgoCD 真实配置源。发布流水线会在 ArgoCD 回写后校验四个连接池参数。
- 新增 `im_db_pool_*` 指标，包括 max/open/in-use/idle/wait count/wait duration/关闭计数，并为连接池 85%/95% 使用率配置预警和严重告警。

这些修复的目标是先让入口稳定完成缓存校验和 Kafka enqueue，把 MySQL 慢转化为可观测、可恢复的 Kafka lag，而不是 Publish 500。如果复测时 `im_db_pool_wait_total` 持续增长或 Kafka 仍无法在 60 秒内归零，再根据 PXC 的 CPU/内存/线程容量将 MySQL `max_connections` 持久化提高到 300–400，不使用临时 `SET GLOBAL`代替配置源。

## 16. 500 对连接池改造后复测

Run ID：`p2p500-fix-20260927-02`。A/B 各建立 500 条 WebSocket，共 500 对、1000 条连接和 10000 次 Publish。三个 IM Pod 均已使用 `meeting_im=24/8`、`hotgo=4/2` 的连接池配置。

| 指标 | 改造前 | 本轮 |
|---|---:|---:|
| WS Ready | 1000/1000 | 1000/1000 |
| Publish ACK | 9946/10000 | 10000/10000 |
| 服务端 500 / socket error | 44 / 10 | 0 / 0 |
| 实时到达 | 9936/9946 | 10000/10000 |
| 实时丢失 / 重复 / 乱序 / 断连 | 10 / 0 / 0 / 1 | 0 / 0 / 0 / 0 |
| ACK P50 / P95 / P99 / Max | - / 2429.954 / - / 3636.045 ms | 662.062 / 1567.569 / 2620.878 / 3156.025 ms |
| 压测期历史回查 | 8580/9946 | 6738/10000 |
| Kafka 排空后 MySQL 精确匹配 | 9946/9946 | 10000/10000 |
| MySQL 缺失 / 错配 / 重复 / 非 ACK 落库 | 0 / 0 / 0 / 0 | 0 / 0 / 0 / 0 |
| Pod 0/1/2 Kafka 峰值 lag | 2490 / 3234 / 2745 | 2259 / 2875 / 2326 |
| Kafka 最慢归零 | 约 4 分钟 | 发送结束后约 4 分 30 秒 |
| MySQL 1040 | 172 次 Pod 日志记录 | 0 |
| Pod 重启 | 0 | 0 |

结论分为两部分：

1. 入口和实时正确性修复有效。10000 次 Publish 全部被接受，实时投递、最终落库、顺序、重复和断连门禁全部通过；连接池上限把全局 MySQL 连接耗尽转化成了进程内排队，没有再出现 `Too many connections`。
2. 容量门禁仍未通过，暂不升级到 1000 对。ACK P95 仍为 1567.569ms，Kafka 未在 60 秒内归零，压测期历史回查因落库未追平只看到 6738 条。

本轮新增指标进一步定位出两个瓶颈：

- 发送阶段 `hotgo` 注册库连接池出现 5841 次新增等待，累计等待约 210.25 秒。`TenantAdapterFor` 当前在命中已创建的租户 adapter 之前仍执行 `tenantByID`，使共库路由的高频操作重复查询 `im_tenant`；4 条注册库连接因此成为 ACK 热路径瓶颈。
- 发送结束 30 秒后，两台 agent 同时以默认 48 worker 执行历史核验，形成 96 路历史查询。三个 `meeting_im` 连接池随后全部达到 24/24；主库新增 6780 次连接等待，累计等待约 11010.16 秒。历史查询与 Kafka persistence 共用连接池，直接延长了 lag 排空时间。
- Pod 2 有一个 100 条批次因 `context deadline exceeded` 降级为逐条写入，100 条最终均成功；三个 Pod 共记录 8 个数据库超时相关日志，没有死信，最终数据库精确核验为 10000/10000。

下一轮前应完成：

1. 为租户元数据增加带失效机制的进程内缓存；`TenantAdapterFor` 命中有效缓存时不得每次读取 `hotgo.im_tenant`，租户停用或配置变更通过现有配置事件主动失效，并保留短 TTL 兜底。
2. 压测程序把实时发压和持久化核验拆成两个阶段：先观察 Kafka 自然排空，再以每机 8–16 个 worker 执行历史核验，避免核验流量反向干扰被测落库吞吐。同时另设“历史读取并发压测”场景验证读写混合容量。
3. persistence 与在线历史查询至少增加独立并发预算；若继续共用连接池，应为 persistence 保留连接或限制历史查询并发，避免读请求耗尽全部 24 条连接。
4. 完成上述改造后仍以 500 对复测，门禁保持 ACK 10000/10000、实时错误为 0、Kafka 60 秒内归零、最终数据库 10000/10000，再决定是否升级到 1000 对。

### 16.1 路由缓存和分阶段核验改造

2026-09-27 已完成下一轮复测所需代码调整：

- MySQL `TenantAdapterFor` 增加 1 分钟租户路由有效期；有效期内直接复用 tenant adapter，不再读取 `hotgo.im_tenant`。
- 同一租户的缓存刷新使用 singleflight 合并，TTL 到期瞬间最多执行一次注册库查询，避免并发击穿。
- `tenant.updated`、`tenant.status.changed`、`tenant.limits.updated`、`tenant.features.updated` 和 `cache.tenant.invalidate` 继续使用现有 Kafka 广播事件；`InvalidateTenantConfigCache` 现在同时使数据库路由缓存失效。失效与刷新并发时通过 generation 校验阻止旧查询重新写入有效缓存。
- 压测配置新增 `history_settle`，默认 5 分钟。实时 drain 完成后先等待该窗口，再发起历史查询，从而单独测量 Kafka 自然排空时间。
- 历史查询默认并发从每机 48 降为 12；历史读取高并发能力后续使用独立读写混合场景验证，不再污染消息落库吞吐结果。

## 17. 路由缓存发布后 500 对复测与延迟改造

Run ID：`p2p500-r3-20260927-03`。A/B 各 500 条 WebSocket、每人发送 10 条消息，总计 10000 次 Publish。

| 指标 | 结果 |
|---|---:|
| WS Ready | 1000/1000 |
| Publish ACK | 10000/10000 |
| 实时到达 / 丢失 | 10000/10000 / 0 |
| 历史回查 / 落库丢失 | 10000/10000 / 0 |
| 重复 / 乱序 / 断连 | 0 / 0 / 0 |
| 总体精确 ACK P95 | 1308.150 ms |
| A / B 精确 ACK P95 | 1121.2 / 1519.2 ms |
| 原报告投递 P95 | 2000 ms（受双机时钟偏差污染） |
| Kafka 最终 lag | 0 |
| `hotgo` pool wait | 0 |

租户路由缓存已经消除 `hotgo` 热路径等待，消息正确性和最终落库全部通过。剩余 ACK 延迟集中在消息 4–6 的突发积压阶段。发压窗口内，`meeting_im` 连接池出现明显等待；同时 Kafka persistence consumer 正在使用同一连接池。Cluster Route RPC 平均约 1–2ms，P2M 队列始终为 0，因此跨 Pod RPC 不是秒级延迟来源。

原投递 P95 不能作为服务端结论：压测程序使用发送机绝对时间戳在接收机计算单向耗时。A 只接受了 5777 个非负样本，而 B 接受了全部 10000 个样本，说明 B 时钟领先 A；A 丢弃负值，B 则把时钟偏差计入延迟。

本次完成以下改造：

1. 压测程序新增同机与跨机两个投递直方图；`delivery_local_p95_ms` 作为门禁，跨机负延迟计入 `cross_machine_negative_latency_samples`，不再静默丢弃后继续生成误导性 P95。
2. 压测消息显式携带 `sender_machine`，旧消息仍可从 `client_mid` 兼容识别来源。
3. 好友关系首次数据库确认后双向回填 Redis，减少双向聊天后续回源。
4. 新增 `im_message_publish_stage_duration_seconds{kind,stage,result}`，覆盖 `relationship_check`、`redis_idempotency`、`redis_sequence`、`kafka_produce` 和整体 `save` 阶段。
5. 新增 `log_client_packets` 配置，默认关闭逐包 INFO 日志，避免每条消息额外 JSON 解析和容器 stdout I/O；需要诊断时才短期开启。

下一轮仍使用 500 对复测。重点比较 `relationship_check`、`kafka_produce` 和 `save` 的 P95，并以 `delivery_local_p95_ms` 判断投递延迟；跨机延迟只有在 chrony/NTP 偏差确认小于 5ms 后才用于验收。数据库连接池暂不扩大，避免再次超过 MySQL 全局 170 连接预算；若 `relationship_check` 已稳定但 pool wait 与 Kafka lag 仍持续增长，再设计 persistence 独立连接预算或批量更新方案。