Java 程序员第 46 阶段18：大模型调用链路追踪，SkyWalking 排查线上性能，生产环境排障实战大模型超时问题定位案例

背景与故障现象排障思路总览指标-链路-日志三线并进第一步Grafana 指标锁定异常窗口第二步SkyWalking 链路定位慢 Span第三步ELK 日志还原现场细节根因分析与验证复盘与长效防线1. 背景与故障现象某电商智能客服系统在大模型升级切换为带 RAG 的 gpt-4o 多轮对话上线后第三天客服坐席集中反馈下午高峰时段用户提问后平均要等 8 秒才出首字超时工单明显增多。系统架构如下nginx → gateway → llm-gateway编排层→ rag-service知识检索→ vector-db向量库/ llm-proxy模型网关→ 外部大模型 API。服务部署在 K8s8 个 llm-gateway PodSkyWalking Agent 全量接入Prometheus Grafana 做指标ELK 做日志链路采样 10%。故障现象来自监控与工单Grafana 上 llm-gateway 的 P99 从日常 1.2s 升至 8.5s且只在 14:00~15:30 出现。SkyWalking 中该时段慢 Trace 占比从 2% 升到 35%。工单系统超时告警5s同时间段增长 6 倍。非高峰时段一切正常。正常时段: P99 ≈ 1.2s 慢 Trace 占比 ≈ 2%高峰时段: P99 ≈ 8.5s 慢 Trace 占比 ≈ 35% 超时工单 x62. 排障思路总览指标-链路-日志三线并进这次排障严格遵循前三篇建立的方法论先用**指标**圈定何时、哪个服务、多严重再用**链路**定位具体哪个 Span 慢最后用**日志**还原为什么慢。三者不是串行而是互相印证。阶段工具要回答的问题输出------------圈定Grafana/Prometheus异常时间窗哪个服务14:00-15:30, llm-gateway定位SkyWalking哪类 Span 慢VectorSearch LLM.Infer还原ELK为什么慢有没有重试/排队线程池打满 重试风暴验证三者联动修复后是否回落P99 回到 1.5s3. 第一步Grafana 指标锁定异常窗口打开 Grafana 的 llm-gateway 大盘先把时间窗放宽到当天确认异常只在 14:00~15:30与峰值时段的客服排班吻合。用按 endpoint 分组的 PromQL 看是哪个接口拖后腿# 按端点分组的 P99histogram_quantile(0.99,sum(rate(skywalking_endpoint_latency_bucket{servicellm-gateway}[5m]))by (le, endpoint))结果显示只有 /v1/chat/completions 飙升其他接口平稳排除全局资源问题。接着看并发线程jvm_thread{servicellm-gateway, stateRUNNABLE} # 接近线程池上限并发线程数在 14:00 后爬升到线程池上限200而 BLOCKED 线程也同步上升——这是关键信号**不是单请求慢而是请求在排队/阻塞**。同时观察 llm-proxy 的成功率指标发现该时段 service_sla 反而平稳在 99.2%说明**外部模型 API 并不慢**。矛头指向内部RAG 检索或线程编排。4. 第二步SkyWalking 链路定位慢 Span在 SkyWalking UI 中按 servicellm-gateway、endpoint/v1/chat/completions、minDuration50005s拉取该时段慢 Trace。抽样一条 8.3s 的 TraceSpan 瀑布如下Total 8300ms├─ Gateway 接收 20ms├─ 鉴权/限流 30ms├─ RAG 编排│ ├─ VectorSearch 4200ms ⚠ 异常长│ └─ ReRank 120ms├─ LLM.Infer 3200ms└─ 后处理/流式返回 760ms但更关键的是另一条 9.1s 的 Trace其 Span 结构不同Total 9100ms├─ Gateway 接收 20ms├─ RAG 编排│ ├─ VectorSearch 150ms (正常)│ └─ ReRank 100ms├─ LLM.Infer (重试 x3) 8600ms ⚠ 三次重试累计│ ├─ attempt-1 超时 3000ms│ ├─ attempt-2 超时 3000ms│ └─ attempt-3 成功 2600ms这说明慢链路有两种形态**A 类 向量检索慢****B 类 模型调用重试风暴**。继续在 SkyWalking 按 endpoint tag 过滤统计两类占比A 类约 60%B 类约 40%。5. 第三步ELK 日志还原现场细节用一条 B 类慢 Trace 的 tid 去 Kibana 检索看到15:02:11.020 [llm-pool-12] INFO LLM 调用开始 modelgpt-4o timeout3000ms15:02:14.021 [llm-pool-12] WARN LLM 调用超时, 触发重试 attempt115:02:17.022 [llm-pool-12] WARN LLM 调用超时, 触发重试 attempt215:02:19.622 [llm-pool-12] INFO LLM 调用成功 attempt3 cost2600mstimeout3000ms 却反复超时结合 llm-proxy 成功率正常怀疑是**客户端超时设置小于模型真实 P99 推理时间**高峰时排队导致偶发超 3s触发重试而重试又加剧了线程占用形成**重试风暴**。再看 A 类用其 tid 检索15:03:02.100 [llm-pool-31] INFO VectorSearch 开始 topK2015:03:06.300 [llm-pool-31] INFO VectorSearch 结束 cost4200ms rows20向量检索在高峰变慢查 vector-db 日志发现该时段有另一个批处理任务在重建索引抢占 CPU 与 IO导致在线检索 P99 从 150ms 涨到 4.2s。6. 根因分析与验证综合三线证据根因有两个且相互放大**客户端超时过短 无退避重试**timeout3000ms 在高峰偶发触发且重试是**立即重试**无退避、无熔断重试请求继续占用线程池线程池打满后所有请求排队延迟雪崩。**资源争用**vector-db 的离线索引重建任务与在线检索同机运行高峰抢占资源VectorSearch 变慢进一步拉长链路、占用线程。验证方式先在预发环境分别复现两个因素。用压测工具模拟高峰并发确认无重试时 P99 仅 4.5sA 类主导加上立即重试后 P99 飙到 9sB 类放大。修复方案下一篇会展开代码改造客户端超时调整为 8s重试改为**指数退避 熔断**Sentinel并限制单请求最大重试 1 次。vector-db 索引重建任务改为低峰凌晨执行并限制其 CPU cgroup 配额。线程池从固定 200 改为按业务隔离rag-pool 与 llm-pool 分离避免互相拖垮。7. 复盘与长效防线修复后上线连续观察三天指标修复前(高峰)修复后(高峰)---------P99 延迟8.5s1.6s慢 Trace 占比35%3%超时工单/日18012线程池打满是否**长效防线建议**指标层对 llm-gateway 增加重试率指标与告警重试率 5% 即告警比延迟告警更早暴露问题。链路层给 LLM.Infer 打 retry_count tagSkyWalking 中可一键筛选重试链路。日志层重试必须 WARN 级并打印 attempt 与 cost便于事后统计。容量层离线任务与在线服务错峰/隔离必要时 HPA 按 P99 自动扩缩容。**小结**本次故障是短超时 立即重试 资源争用三者叠加。正是前三篇搭建的指标、链路、日志三件套让我们在 40 分钟内从用户说慢定位到两个确切根因。下一篇我们把这次经验沉淀为从链路洞察到代码改造的性能优化闭环。