用 AI 定位瓶颈:指标、日志与 pprof 联动
压测发现问题之后,最常见的低效动作是「凭直觉改一处再压一遍」。瓶颈定位要靠三条互相独立的证据链交叉验证:指标回答「哪一层饱和了」,日志回答「请求死在哪一步」,剖析(profiling)回答「CPU 与内存具体花在哪里」。AI 在这件事上的正确用法不是替你猜,而是把零散现象整理成可执行的假设清单,并明确每条假设需要什么证据、怎么采集。
三条证据链各自回答什么
| 证据链 | 观察对象 | 能回答的问题 | 典型采集入口 |
|---|---|---|---|
| 指标(metrics) | 应用:QPS、P99、错误率、线程池、连接池、goroutine;系统:CPU、内存、磁盘、网络、上下文切换;中间件:慢查询、缓存延迟、MQ 堆积 | 哪一层先饱和、饱和发生在哪个时间点 | 应用大盘、vmstat、ss -s、redis-cli --latency、慢查询日志 |
| 日志(logs) | 错误码分布、首个异常栈、慢请求阶段耗时 | 失败与变慢发生在哪个步骤、是否有重试与超时 | 应用日志、接入层日志、慢请求日志 |
| 剖析(profiling) | CPU 热点、内存分配、goroutine 栈、阻塞与锁竞争 | 资源到底被哪段代码消耗 | go tool pprof、火焰图、线程栈 dump |
三条链缺一不可。只看指标容易把「排队」当成「算力不足」;只看火焰图可能在压测机打满时得出错误的 CPU 热点结论。
让 AI 输出「假设 → 证据 → 采集」表
现象:定速压测到 3000 QPS 时 P99 从 38ms 跳到 260ms,服务端 CPU 88%,
系统态占比从 12% 升到 31%,上下文切换从 23k/s 升到 96k/s,
错误码以 503 为主,DB 与 Redis 自身指标平稳。
请输出候选假设表,列:假设 | 该假设成立的证据 | 采集命令或入口 | 若为真的预期观测 | 排除该假设需要的数据。
要求:
1. 至少 4 条假设,覆盖应用、系统、中间件三层;
2. 每条假设必须给出可执行命令(写全参数),不确定的工具参数请标注"待核实",不许编造;
3. 按"先便宜后昂贵"排序:先抽样日志与指标,再上剖析;
4. 最后给出验证顺序,说明为什么先验证第一条。
「预期观测」这一列是关键:先写下「如果这个假设为真,我会看到什么」,再去采集。否则数据一到手,人总会不自觉地往已有结论上套。
假设表样例
| 假设 | 支持证据 | 采集方式 | 若为真的预期观测 |
|---|---|---|---|
| 对象分配过多引发 GC 抢占 CPU | GC CPU 占比升至 8%,系统态升高 | GODEBUG=gctrace=1 ./app、/debug/pprof/heap?debug=1 | GC 频率超过每秒 1 次、存活堆接近 GC 前堆 |
| 响应体过大导致序列化与网络开销 | 系统态 CPU 高、平均响应体积增长 | 访问日志响应体大小统计、encoding/json 热点 | CPU 剖析中 encoding/json 占比靠前 |
| 数据库连接池排队 | 连接池 active 顶满、获取连接耗时长 | 连接池指标、SHOW PROCESSLIST | active 长期等于上限、大量连接处于 Sleep 之外的等待态 |
| 下游 Redis 延迟毛刺 | 客户端超时计数上升 | redis-cli --latency -h 10.0.0.9 | 出现毫秒级周期性毛刺、--latency-history 有峰值 |
| 锁竞争或单点串行化 | 上下文切换暴涨、延迟线性上升 | block 与 mutex 剖析、线程栈 dump | block 剖析中集中于同一把锁或同一个 channel |
按「先便宜后昂贵」排序很重要:日志抽样和指标几乎零成本,剖析会带来额外开销,压测过程中抓 CPU 剖析更要控制时长。
采集命令清单
# 1. 系统层:CPU、内存、调度、上下文切换
vmstat 1 10
pidstat -w -u -t -p <pid> 1 10 # 按线程看切换与 CPU
# 2. 网络与连接队列
ss -s # 汇总:连接数、TIME_WAIT、端口耗尽迹象
ss -lnt # 监听队列:Recv-Q 非零即堆积
nstat -az | grep -E 'TcpRetrans|ListenDrops|TcpExtListenOverflows'
# 3. 中间件
redis-cli -h 10.0.0.9 -p 6379 --latency
redis-cli -h 10.0.0.9 -p 6379 --latency-history -i 5
mysql -e "SHOW PROCESSLIST" | head -20
mysqldumpslow -s t -t 10 /var/log/mysql/slow.log # 按总耗时排序的慢查询
# 4. 应用剖析(Go)
go tool pprof -http=:6060 'http://10.0.0.12:6060/debug/pprof/profile?seconds=30'
curl -s 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1' | head -30
go tool pprof http://10.0.0.12:6060/debug/pprof/block
| 输出 | 判读 |
|---|---|
vmstat 的 cs 随压力超线性增长 | 锁竞争、线程数失控或 IO 阻塞,而非算力不足 |
vmstat 的 r 长期大于核数 | 有排队,加并发不会提升吞吐 |
ss -lnt 的 Recv-Q 持续非零 | 应用 accept 不过来或处理线程被占满 |
nstat 出现重传与 listen 溢出 | 网络或内核队列在丢弃连接,吞吐上限由内核决定 |
redis-cli --latency-history 有周期毛刺 | 缓存侧毛刺会放大成全局长尾 |
goroutine?debug=1 栈大量聚集在同一函数 | 该函数是阻塞点:等锁、等 IO 或等下游 |
CPU 剖析 top -cum 指向 runtime.mallocgc | 分配速率过高,先降低对象分配再谈优化算法 |
用日志把范围收窄
指标告诉你「慢」,日志告诉你「慢在哪一步」。压测期间日志要做三件事:按错误码聚合、按耗时区间聚合、保留可复现的样本请求。
# 错误码分布:先确认错误性质,再谈性能
awk '{print $9}' access.log | sort | uniq -c | sort -rn | head
grep -c 'context deadline exceeded' app.log
# 慢请求样本:取一条完整链路,人工核对阶段耗时
grep '\[slow\]' app.log | awk -F'total=' '{print $2}' | awk '{print $1}' | sort -n | tail -20
| 日志特征 | 指向 |
|---|---|
| 错误集中在超时类异常 | 下游或自身排队,先看超时预算与重试次数 |
| 首个异常栈之后同类异常刷屏 | 连锁反应,只看第一个异常栈 |
| 503 占比高且集中在压测后段 | 熔断或限流触发,或连接不被上游接受 |
| 慢请求的某阶段耗时随压力增长 | 该阶段存在共享资源排队 |
验证与闭环
- 一次只改一个变量:改连接池上限与改序列化库同时做,压测结果无法归因。
- 改完必须重压同一档位、同一时长,并把前后数据放进同一张表对比。
- 判断修复是否有效,看的是拐点是否右移,而不是峰值吞吐是否提高。
- 结论要能落到证据链上:指标定位层级、日志确认环节、剖析落到代码行,三者对齐才算定位完成。
- AI 给的工具参数一律先核对:用
<工具> --help或官方文档确认后再执行,凭记忆拼出来的参数很可能是错的。
小结:指标、日志、剖析三条证据链分别回答「哪一层饱和」「请求死在哪一步」「资源花在哪段代码」;让 AI 产出「假设 → 证据 → 采集 → 预期观测」的表并先写预期再采集,用 vmstat、ss -s、redis-cli --latency、慢查询日志和 go tool pprof 逐条验证,一次只改一个变量,最后用拐点是否右移来判断修复是否真的有效。