pro/im_server
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity
Files
f9f7321b116e6f7f013677c645841a47f97cd022
im_server/docs/test/IM-单聊压测Pod日志根因分析与改进方案-20260927.md
T

19 KiB
Raw Blame History

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 对档位。
Reference in New Issue View Git Blame Copy Permalink