线上问题排查：连接抖动、消息延迟与内存增长

本章目标：按「先定范围、分层量化、再动手」的顺序处理 im-go 线上最高频的三类问题——连接抖动（flapping）、消息延迟、内存增长；每个现象都给出判定依据与可复制的命令，而不是靠猜。

1. 统一排查路径

  • 定范围：单台网关还是全集群？只影响新连接还是存量连接？几点开始？与最近的发布/配置变更对齐时间线。
  • 分层量化：客户端 → 负载均衡/Nginx → 网关 → 逻辑层 → Redis/MySQL，每一层至少要有一个数字（在线数、队列长度、RPC P99、Redis 延迟）。
  • 先留证再动手：ss、lsof、pprof、日志片段先落到 /tmp/diag-$(date +%s)/，重启会销毁现场。
  • 一次只改一个变量，改完用同一组命令复测，否则无法归因。

网关至少要暴露这四个内部数字，排障时才有对照物：在线连接数（im_online_connections）、待确认消息数（im_ack_pending）、投递失败原因分布（im_deliver_failed_total）、协程数（go_goroutines）——都来自第 12 章的指标清单。

2. 连接抖动：先看心跳与代理超时

ss -s                                                     # 全局 socket 统计：总数、TIME_WAIT
ss -tn state established '( sport = :8080 )' | wc -l      # 内核里的实际建连数
lsof -p $(pgrep -f bin/gateway) | wc -l                   # 进程 fd 数，与在线连接数×2 对照
netstat -s | grep -iE 'listen|overflow|retrans|timeout'   # 队列溢出与重传
sudo grep '"event":"conn_close"' /var/log/im-go/gateway.log | grep -o '"reason":"[^"]*"' | sort | uniq -c | sort -rn | head
redis-cli INFO clients                                    # connected_clients / blocked_clients
sudo tail -200 /var/log/nginx/error.log | grep -i 'upstream timed out'

判读依据：

观测结论
在线数曲线呈锯齿、重连率升高代理空闲超时小于心跳周期：Nginx proxy_read_timeout 默认 60 秒，心跳 30 秒要留足余量（第 14 章）
每 30 秒或 60 秒成批掉线定时器效应：负载均衡会话超时、心跳参数或客户端后台节流
listen queue overflow 计数上涨全连接队列满，调 somaxconn 与 listen backlog（第 13 章）
TIME_WAIT 数量暴涨服务端主动关闭过多：健康检查用短连接、或大量连接被踢后未复用
只有某个运营商/地区掉线中间设备或 NAT 表项超时，缩短心跳周期并启用 TCP keepalive
日志出现 too many open filesLimitNOFILE 没调，fd 打到上限后新连接被拒

比曲线更可靠的是内核与进程内部数字的差值：ss 数出的 ESTABLISHED 远大于进程内在线数，说明有幽灵连接（半开连接未被心跳回收）；两者接近但都远大于客户端实际在线数，说明客户端一直在重连而旧连接没被清理。同时看第 12 章的 im_conn_total{result} 建连/断连速率，两者同步抬升就是抖动。再配合日志里的关闭码——1006 是异常关闭（网络断开、代理掐断），1000/1001 是正常或主动下线，比例突变的方向就指向代理层还是客户端。

3. 消息延迟：把投递链路拆成六段

一次单聊投递要经过六个可度量的阶段：第 12 章的 im_msg_deliver_latency_seconds{stage="push"} 只给出端到端数字，要定位就得给每段补一个 stage 标签（decode、auth、route、rpc、db、push、other），之后一次采样就能指认大头：

阶段典型瓶颈主要命令
网关收包与解码大帧、JSON 编解码、单帧超限go tool pprof CPU profile
会话与鉴权校验Redis 往返、JWT 校验成本redis-cli --latency
路由查询慢查询、大 key、命中率下降redis-cli SLOWLOG GET 10
gRPC 调用逻辑层连接池排队、序列化、下游超时pprof block profile、gRPC 指标
落库慢 SQL、行锁、连接池耗尽SHOW FULL PROCESSLIST、慢查询日志
投递到对端并写回慢客户端导致发送队列积压网关队列长度、写超时计数
go tool pprof -top 'http://127.0.0.1:6060/debug/pprof/profile?seconds=30'
go tool pprof -top 'http://127.0.0.1:6060/debug/pprof/block'     # 谁在等锁、等通道
redis-cli --latency -h 127.0.0.1                                 # 排除 Redis 网络往返
redis-cli SLOWLOG GET 10
mysql -N -e "SHOW FULL PROCESSLIST" | awk '{print $6}' | sort | uniq -c | sort -rn | head
grep -o 'cost_ms=[0-9]*' /var/log/im-go/logic.log | sort -t= -k2 -n | tail -20   # 上行处理耗时 Top20

三句判读经验：P50 正常而 P99 抬升多为排队（锁竞争、连接池、发送队列），去看 block profile；P50 与 P99 一起抬升才是资源饱和（CPU、GC、Redis 单点），先扩容再优化；只有特定用户或特定群慢通常是群扩散（fan-out）写放大或历史消息过长，与机器无关。各段之和与端到端耗时的差值（stage="other"）如果超过 10%，说明还有没埋到的阶段，先补埋点而不是继续猜。

4. 内存增长：连接 map、goroutine 与发送队列

curl -s 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1' | head -40   # 协程数与栈聚合
go tool pprof -inuse_space http://127.0.0.1:6060/debug/pprof/heap          # 存活对象
go tool pprof -alloc_space http://127.0.0.1:6060/debug/pprof/heap          # 分配热点
grep -E 'VmRSS|Threads' /proc/$(pgrep -f bin/gateway)/status               # 进程真实占用
ss -s                                                                      # 与连接数对照
GODEBUG=gctrace=1 /opt/im-go/current/gateway -conf /opt/im-go/configs/config.yaml   # 临时实例，换端口跑
根因表现处理
连接 map 未删conns map[connID]*Conn 只关连接不删键；同设备重连覆盖了 key，旧键成孤儿所有清理收口到唯一一个 remove()，defer 调用，并周期比对 map 长度与在线数
goroutine 泄漏读循环退出后写循环仍阻塞在 channel，或 ticker 未 Stop、心跳 goroutine 没有退出信号用 close(done) 统一广播退出；用 goroutine?debug=1 看栈是否集中在同一条 chan receive
发送队列积压慢客户端写不出去，send chan []byte 越堆越长，内存随慢客户端数量上涨有界队列 + SetWriteDeadline，超时直接踢连接（第 02 章）
本地缓存无界路由缓存、群成员缓存只写不淘汰一律加 TTL 与容量上限（LRU），禁止无界 map
Redis 端增长route:* 键没设过期时间，幽灵路由堆积登录写入必须带 EXPIRE；redis-cli INFO memory 与 --bigkeys 定期看

判定顺序固定：先看 VmRSS 是单调上涨还是「涨到某值后回落」（后者是正常 GC 行为，前者才是泄漏）；再用 heap 的 inuse_space 定位是 map、*Conn 还是 []byte 在占；goroutine 数单调上涨不回落，一定是泄漏，与内存曲线同向基本可以定案。重启前先抓 goroutine 与 heap——重启之后现场就没了。

5. 留证包：一次故障归档一次

D=/tmp/diag-$(date +%s) && mkdir -p $D
ss -s > $D/ss.txt
lsof -p $(pgrep -f bin/gateway) > $D/lsof.txt
curl -s 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=2' -o $D/goroutine.txt
curl -s 'http://127.0.0.1:6060/debug/pprof/heap' -o $D/heap.pb.gz   # 默认即 pprof 格式
redis-cli INFO all > $D/redis-info.txt
redis-cli SLOWLOG GET 50 > $D/redis-slowlog.txt
tail -5000 /var/log/im-go/gateway.log > $D/gateway.log

三条纪律：抓取顺序先内核后进程（内核计数变化最快，越早抓越准）；每个文件都记录抓取时刻，便于和监控曲线对齐；归档进故障单并与当天的发布、配置变更放在一起——同类问题第二次出现时，两份留证包一对比就能看出差异。

常见坑

坑现象做法
一上来就重启现场丢失，一周后再犯先 ss/lsof/pprof 留证再重启
只看进程内在线数与内核连接数偏差大，问题被掩盖两边同时看，差值即幽灵连接
把 504/断连归因于「网络抖动」其实是自己配的超时小于心跳对照心跳周期与代理超时（第 14 章）
调大超时当修复断连变成「更晚的断连」先定位是心跳、代理还是负载均衡
内存涨了就加大机器泄漏仍在，只是晚几天爆用 heap 找到持有者，改代码
生产长期开着 mutex profile自身开销拖慢服务只在排查窗口开启，采完设回 0
pprof 端口对公网开放内部结构甚至内存快照泄露只监听 127.0.0.1:6060，与监控端口（第 12 章的 9101）分开
忽略变更时间线找不到触发点，反复试错与发布、配置、流量变更对齐时间

小结：三类问题共用一条路径——先定范围、再分层量化、留证后再动手。连接抖动查心跳与代理超时的关系（ss -s、netstat -s、在线数与内核连接数的差值），消息延迟把投递链路拆成六段逐段埋点（pprof block、Redis SLOWLOG、MySQL 慢查询），内存增长优先怀疑连接 map、goroutine 与发送队列三处泄漏（goroutine?debug=1、heap inuse_space、VmRSS 曲线），而重启永远是最后一步动作。

笔记加载中…

标签：#IM #Go #项目实战

返回知识库