那天下午两点零七分第一条告警弹了出来模型推理服务 P99 耗时从平时的 180ms 直接拉高到 2.4 秒错误率从 0.1% 升到 2.3%。业务方在群里连续追问运营同事已经在准备对外公告。作为负责推理链路的后端我的第一反应是查模型本身——毕竟前一天刚切了新版本模型谁都会先怀疑自己刚改动的东西。结果 GPU 利用率曲线平稳得可怕各 batch 的纯推理耗时也没有任何异常。模型没忙服务却快不行了。排查到最后问题指向了 Redis 缓存集群。这是一个特别典型的案例模型推理响应慢表面上是算法问题实际是缓存基础设施被拖垮。整个过程踩了不少坑包括一开始在模型侧耽误了将近一个小时后面又因为连接池参数绕了弯路。这篇文章把完整的排查思路、命令证据、根因复盘和事后治理方案写出来希望能帮到正在做推理服务优化的后端、SRE 和负责模型上线的同学。就算你没遇到过同样的事故这套排查链路也值得收藏一份。1. 故障表象与第一轮排查GPU没忙耗时却翻倍1.1 告警形态与业务反馈先分清变慢和错误故障复盘第一步是先把现象描述精确到数字。我当时拉取了三个核心指标P99 耗时、错误率、每秒请求量。三个指标放在一起看能快速区分几种不同的故障形态。请求量没有突变说明不是流量洪峰把服务压垮了。错误率从 0.1% 升到 2.3%说明有一部分请求已经直接失败。P99 耗时从 180ms 涨到 2.4s说明另外一部分请求还在缓慢执行但没有立刻报错。这个组合非常关键如果只是延迟升高、错误率却几乎不变通常是某个下游组件变慢系统还在硬扛如果错误率同步上升说明下游已经出现拒绝服务或线程池耗尽。我们这次的曲线属于先变慢后少量报错意味着罪魁祸首是一个让命令无法及时返回的组件而不是一个直接拒绝连接的组件。业务方反馈的细节也印证了这一点他们观察到的不是接口完全打不开而是转圈转很久偶尔超时失败。这种钝刀子割肉的体验在缓存集群性能退化时非常常见。1.2 排除模型推理自身GPU、batch、前后处理既然表象是模型推理响应慢第一件事就是把模型推理链路本身从头到尾验证一遍。我当时的排查顺序很直接看 GPU 利用率如果模型推理变慢GPU 利用率往往会跟着波动。结果利用率曲线非常平稳说明 GPU 计算没有成为瓶颈。看推理日志的耗时分布模型侧每个 batch 的推理时间 p50、p99 都正常没有出现单 batch 特别慢的情况。看 batch 大小和并发配置新版本模型上线时是否调整过 batch size、max latency、动态 batching 参数对比之后发现配置没有变化推理服务的线程池和队列也没有堆积。看前后处理逻辑tokenizer、特征拼装、结果后处理有没有因为新版本模型而变化。日志显示这部分耗时正常。这一轮排查大概花了四十分钟。结论是模型计算、前后处理全都正常问题不在算法侧而在给模型喂数据的那条链路上。1.3 链路追踪把矛盾指向特征加载环节确定模型本身没问题之后我开始看全链路 trace。我们用的 SkyWalking每个请求都会打一条完整的 Span 链。从 trace 页面可以清楚看到请求时间被分成了几段网关转发、鉴权限流、特征加载、模型前置处理、GPU 推理、后处理、日志写入。正常情况下GPU 推理是占比最大的一段但这次事故中特征加载段平均耗时 1.6 秒占了整体耗时的 70% 以上。特征加载这步走的就是 Redis 缓存集群。这里很容易让人迷惑的一个点缓存命中率明明是 98.5%并没有明显下降。我当时也怀疑过是不是缓存穿透或者缓存击穿——比如某个 key 过期后大量请求同时回源数据库。但数据告诉我们命中率没跌说明绝大多数请求都命中了缓存问题不在于回源而在于即使命中了Redis 返回数据也特别慢。1.4 推理服务为什么离不开缓存特征、路由、AB配置借这次故障我重新梳理了一下推理服务对 Redis 的依赖关系这也是很多同学容易忽略的地方。模型推理并不是简单地把请求扔给 GPU 算一下推理之前通常要拼装完整的特征向量用户画像特征性别、年龄、兴趣标签、历史行为序列高频更新缓存在 Redis。物料特征商品/内容/广告的 embedding 向量、分类信息模型推理前要批量加载。模型版本与动态权重灰度切流、AB 实验参数经常从 Redis 拉取。分布式锁模型热加载、动态配置更新时需要分布式锁保证多副本一致性。所以推理快不快这件事很多时候不取决于 GPU而取决于你能不能及时拿到特征。如果 Redis 集群某个节点出现性能问题哪怕只有一个关键 key 访问慢也会拖垮整条推理链路。这次故障就是最真实的例子。2. 客户端超时不是客户端背锅Lettuce 连接池与超时参数的真相2.1 RedisCommandTimeoutException 到底是什么在超时应用日志里出现了一条非常经典的异常org.springframework.data.redis.RedisConnectionFailureException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException第一次看到这个报错很多人会下意识觉得是连接不上 Redis。其实不是。这条异常的意思是TCP 连接是建立成功的命令也已经发出去了但是客户端在配置的超时时间内没有收到服务端的响应。Lettuce 客户端对每次命令执行都会设置一个超时时间。如果服务端处理命令太慢或者网络传输太慢或者命令在客户端队列里排队太久都会触发 RedisCommandTimeoutException。换句话说超时只是症状具体原因必须继续往下挖。我开始排查时发现连接池的配置长这样spring: redis: timeout: 2000ms lettuce: pool: max-active: 8 max-idle: 8 min-idle: 0 max-wait: -1ms这个配置有两个非常危险的点我在压测里逐一验证了。2.2 连接池默认参数max-wait 等于 -1 有多危险第一个危险点是max-active: 8。对于 Spring Boot 2.x 的 Redis 客户端来说如果你没有引入 commons-pool2 或者没有手动设置连接池参数Lettuce 底层是共享连接、多路复用的。但一旦打开连接池每个线程拿连接时就要受 max-active 限制。8 个连接看上去不少但在高并发推理服务里完全不够。第二个危险点是max-wait: -1ms这表示线程从连接池获取连接时如果池子里没有空闲连接会一直阻塞等待永远不会超时。连接池耗尽之后请求线程全部卡在等连接这一步接口表现就是 P99 持续飙升、线程堆积、CPU 全被无谓的上下文切换吃掉。我通过 jstack 抓线程堆栈看到大量业务线程阻塞在 Lettuce 的pool.getConnection()方法上这基本实锤了连接池已经打满。2.3 本地压测复现从能跑到超时的距离为了把问题复现出来我用 Redis 自带的 redis-benchmark 对单个节点做标准 GET 压测。标准的小 value 场景下单节点可以扛到几万 QPS说明 Redis 节点本身的处理能力没有退化。但我们真实业务场景不是小 value而是读取几百 KB 甚至上 MB 的特征值。于是我写了个简单压测脚本模拟推理服务真实访问模式每个请求从 Redis 读取一个特征 key做反序列化然后返回。结果非常明显并发 20 时P99 在 50ms 左右勉强能接受。并发 100 时P99 涨到 800ms开始出现超时日志。并发 200 时P99 直接超过 2s连接池被打满max-wait 无限等待的坑被引爆。这个复现过程说明两件事客户端配置确实有责任但更核心的问题在于单个命令的耗时被拉长了——一个命令在连接上占用的时间越长连接池里的连接就越容易被占满其他请求就越拿不到连接。2.4 判断客户端还是服务端的三个抓手踩过这个坑之后我总结了一套快速定位到底是客户端配置问题还是服务端性能问题的方法三个抓手按顺序来看基础 RTT在正常时段用redis-cli --latency直接测试到 Redis 节点的网络延迟。如果 RTT 正常通常 1ms 以内说明网络链路没有大问题。看服务端指标Redis 节点 CPU 利用率、网卡带宽、内存、慢查询数量。如果某个节点 CPU 已经 80% 以上或者网络吞吐接近打满问题大概率在服务端。看命令耗时分布用 slowlog 看慢命令的真实执行耗时。客户端超时可能是假象但 slowlog 里的时间是 Redis 亲口承认的。以下是三种情况下的判断对照现象客户端问题占比服务端问题占比RTT 正常节点 CPU 低但客户端超时高优先检查连接池/超时参数低节点 CPU 高slowlog 有大量慢命令低高重点查大 key/热 key/持久化节点间网络丢包或跨可用区延迟大中需要看拓扑中属于基础设施问题3. 服务端体检大Key、热Key、持久化阻塞这三类隐形杀手3.1 大Key特征值膨胀带来的网络与反序列化双重开销模型推理场景是生产大 Key 的重灾区。特征数据经常以序列化后的对象存入 Redis比如把某个用户的所有兴趣向量拼成一个大的 String value。正常情况下一个特征向量也就几百字节但一旦你把几十个向量拼接、再经过 JDK 序列化或 JSON 序列化体积轻松突破 1MB。大 Key 的危害是连锁的网络传输时间变长。1MB 的 value 在千兆网卡上传输需要近 10ms算上 TCP 窗口和协议开销实际感受会更久。客户端反序列化耗时变长。拿到 1MB 数据后Jackson 或 Kryo 反序列化可能又花掉十几毫秒。内存和内存碎片压力增大触发淘汰或者内存碎片整理时进一步拖慢节点。删除、迁移大 Key 时可能造成主线程阻塞尤其在集群模式下重新分片时会特别明显。这里还要提一下 Redis 数据类型的选择。很多人习惯什么缓存都用 String但特征数据其实更适合 Hash一个用户的所有特征作为 field 存在同一个 Hash 里每次只读取需要的 field而不是一次性把整个对象拉回来。后续根因修复时我们就是这么改的。3.2 热Key单个分片被打爆的木桶效应Redis Cluster 的数据分布规则是对 key 做 CRC16 运算然后对 16384 个槽取模每个分片负责一部分槽。问题在于不管你有多少个分片一个 key 只能落在某一个槽位也就是某一个分片上。如果某个 key 的访问量特别高比如爆款商品的特征 key那所有访问流量都会打在同一个分片上。其他分片可能 CPU 只有 5%这个分片却已经 90% 了。这是典型的木桶效应集群的总容量看起来还有余量但单个分片的瓶颈直接拖垮全局。这里顺便回答一个很多同学会问的问题哨兵模式和集群模式的区别到底是什么简单说哨兵模式解决的是高可用主节点挂了自动切换从节点集群模式解决的是水平扩容数据按槽位分散到多个分片。但集群模式并不能自动解决热点倾斜因为 key 的槽位是哈希计算出来的热点 key 再热也只能由一个分片扛。理解了这一点你就知道为什么加节点不一定能救热 Key——你加再多的分片热点 key 还是固定在那一个分片里。3.3 RDB fork 与 AOF rewrite持久化引发的周期性卡顿第三种容易被忽略的隐形杀手是持久化阻塞。Redis 是单线程模型处理命令和触发持久化在同一个主线程里。RDB 快照的流程是 fork 一个子进程子进程负责把内存数据落盘。fork 操作本身需要复制主进程的页表内存越大fork 耗时越长。如果实例内存有几十 GBfork 可能会阻塞主线程几百毫秒甚至更久。AOF rewrite 也是同样的机制重写时会先 fork 子进程。一旦发生这种阻塞所有命令都会卡住表现就是周期性的响应变慢。这次故障的时间点正好赶上每小时一次的 AOF 重写窗口虽然不是根因但加重了 Redis 节点的整体负载。用INFO persistence里的latest_fork_usec字段可以直接看到最近一次 fork 的耗时。3.4 一张表区分三类问题看指标、看时机、看分布排查时最容易犯的错是只盯着一个指标。我建议在监控告警里把三类问题的特征分开来看问题类型主要症状高发时机核心定位手段大 Key响应变慢、网卡带宽高、删除/迁移卡顿不限时段--bigkeys、slowlog热 Key单个分片 CPU/带宽高其他分片空闲流量高峰、运营活动--hotkeys、节点监控持久化阻塞周期性卡顿latest_fork_usec 很大定时持久化窗口INFO persistence用这张表对照一下当时的现象非常清晰某个分片 CPU 接近 90%网卡带宽打满其他分片 CPU 都在 10% 以下slowlog 里大量 GET 命令耗时几十毫秒。问题指向大 Key 和热 Key 叠加在同一个分片上。4. 用 slowlog、--bigkeys、--hotkeys 把根因钉死在证据上4.1 先从 slowlog 看慢命令长什么样慢查询日志是排查 Redis 性能问题第一站。执行命令redis-cli -c -h node_ip -p 6379 slowlog get 20输出结果主要看几个字段time时间戳、execution_time执行耗时微秒、command完整命令。我看到的 slowlog 里大量是 GET 命令耗时普遍在 30ms 到 120ms 之间正常情况下这个值应该是 0.5ms 左右。顺便提醒一句slowlog 默认只保留最近 128 条slowlog-log-slower-than默认阈值是 10000 微秒10ms。如果生产环境平时几乎没有超过 10ms 的命令那遇到的每一条慢查询都值得重点看。4.2 --bigkeys 的正确姿势与生产环境注意事项慢日志只是入口下一步要找出哪个 key 体积异常大。命令是redis-cli -c -h node_ip -p 6379 --bigkeys这个命令会遍历整个 key 空间统计每个类型里最大的 key。需要注意两点它并不是只查几个 key而是全量扫描在几十 GB 的大实例上会产生明显开销。我建议在低峰期运行或者加上-i 0.01让每条扫描命令之间间隔 0.01 秒降低对业务的影响。它输出的是每种数据类型里最大的几个 key但不代表这些 key 就是性能瓶颈。大 key 是否成为瓶颈还要结合访问频率来看。我们在这次故障里用 --bigkeys 找到了一个user:profile:{hot_user_id}类型是 Stringvalue 约 1.8MB。这个 value 是从数据库加载的一大坨用户画像加上兴趣向量经过 JDK 序列化后整体塞进去的。晚点我们复盘时发现这个 value 在写入前其实已经做过一次 JSON 序列化两层序列化叠加体积膨胀得厉害。4.3 --hotkeys 有个前置条件内存淘汰策略得是 LFU找完大 key下一步找哪些 key 被疯狂访问。--hotkeys 这个命令有一个硬性前提Redis 的内存淘汰策略必须是 LFU 相关策略否则命令会直接报错提示无法获取足够信息。先查看当前的淘汰策略redis-cli -c -h node_ip -p 6379 CONFIG GET maxmemory-policy如果返回的是noeviction或者allkeys-lru这类非 LFU 策略--hotkeys 是不能用的。要临时开启redis-cli -c -h node_ip -p 6379 CONFIG SET maxmemory-policy allkeys-lfu这里必须强调修改 maxmemory-policy 会改变缓存淘汰行为如果实例设置了 maxmemory且内存接近上限突然改成 LFU 可能触发一批 key 被淘汰。生产环境一定要先评估再执行最好在低峰期操作。好在我们的 Redis 集群内存水位不高临时切换风险可控。开启后执行redis-cli -c -h node_ip -p 6379 --hotkeys输出里会展示访问频率最高的 key。我们看到一个非常显眼的条目item:feat:{material_id}访问频率远超其他 key而且这是一个爆款物料在活动期被集中请求导致的——线上正好在跑运营活动所有推理请求都要读这个物料特征。4.4 证据链闭合一个不起眼的特征Key成了最大瓶颈到这里证据链基本闭合了。我再把几条线索并列在一起大 keyuser:profile:{hot_user_id}1.8MB被每次请求读取。热 keyitem:feat:{material_id}访问频率极高每秒被读取上万次。分片分布用CLUSTER KEYSLOT分别查了这两个 key发现它们恰好落在同一个节点上。redis-cli -c -h node_ip -p 6379 CLUSTER KEYSLOT user:profile:{hot_user_id} redis-cli -c -h node_ip -p 6379 CLUSTER KEYSLOT item:feat:{material_id}两个 key 的槽位都指向同一台节点。于是这台节点同时承受大 value 的网络传输压力和超高 QPS网卡带宽直接被打满节点上所有命令都开始排队。连接池耗尽、客户端超时、P99 飙升全部都是这个根因的次生灾害。我们原本只在大盘上看了集群整体 CPU 和带宽完全没注意到单分片已经打满。这也是这次故障一个非常重要的教训Redis 集群的监控必须按分片维度拆开看不能只看平均值。5. 根因复盘特征缓存的热点倾斜是如何发生的5.1 根因还原新版本模型引用了超大特征组把所有线索拼起来根因链条是这样的前一天晚上团队上线了新版本模型。新模型的特征工程新增了一个用户兴趣向量组为了减少推理时多次访问 Redis特征工程同学把这个向量组整体序列化后写进了同一个 String key也就是user:profile:{hot_user_id}。如果只是这个 key 大其实问题还好办毕竟单个用户访问量有限。但线上同时还在跑运营活动某个爆款物料的特征 key 访问量飙升。这两个 key 的槽位又恰好被分配到同一个分片节点上。结果就是这个分片既要处理 1.8MB 大 value 的高昂传输成本又要扛住超高 QPS 的访问压力。单分片网卡带宽先被打满随后 CPU 跟着飙高。因为 Redis 是单线程处理命令带宽拥塞导致所有命令的响应时间变长包括那些和热点无关的普通 key 读写。于是整个集群的表现就是整体响应变慢而实际瓶颈只在一台节点上。5.2 止血三板斧本地缓存兜底、熔断降级、临时扩容定位到根因之后第一要务不是优雅优化而是先让线上恢复。我们当时做了三个动作第一步应用侧加本地缓存。用 Caffeine 在推理服务进程内缓存高频特征 keyTTL 设为 30 秒。这样部分流量直接在本地命中不再打到 Redis 热点节点上相当于给 Redis 卸了一半的负担。这一步效果立竿见影P99 从 2.4s 降到了 800ms 左右。第二步做超时熔断和降级。把 Redis 操作的超时时间从 2s 调低到 500ms一旦 Redis 超时不再无限等待而是降级到一个异步批量加载特征的任务虽然耗时比缓存会慢一些但至少接口不会因为线程池耗尽而全部失败。第三步临时扩容和迁移。把承载热点 key 的分片上的部分槽位迁移到其他空闲节点但这只能缓解分片压力不能根治大 key 和热 key。所以把这一步放在应急预案里用来争取时间。5.3 根治方案Key拆分与缓存结构重构止血之后花了大概两天时间做根治方案。核心动作有三个一是把大 value 拆掉。user:profile:{hot_user_id}从 String 改成 Hash 结构user:features:{userId}每个 field 对应一个兴趣向量或画像标签代码里只读取本次推理需要用到的 field不再一次性拉全量。序列化方式从 JDK 序列化换成了 Protobuf同理一条数据体积从 1.8MB 压缩到 400KB 左右。二是给极端热 key 加随机副本。对于item:feat:{material_id}这种预测不到流量峰值的 key在写入时写多个副本比如 key 后面加:{0..N}的后缀读取时随机选一个副本。这样可以把访问流量分散到多个槽位避免单个分片被打爆。注意这个方案只适合读多写少且可以接受短暂不一致的场景写时要用 pub/sub 或者其他手段同步副本。三是增加异步预热任务。特征数据不再由推理请求触发时现算而是由专门的预热任务在后台批量写入缓存并且设置合理的 TTL 和最大 value 大小限制。超过阈值时强制拆分不允许任何大于 1MB 的 value 进入缓存。5.4 复盘记录从故障到预案的三条规则故障处理完团队做了一次复盘沉淀成三条规则我认为比修复本身更有价值模型上线之前必须做依赖容量评估。不仅要评估 GPU 算力还要评估推理链路依赖的 Redis QPS、带宽、内存增长尤其是新增特征缓存时。大 key 治理要纳入日常巡检。每次发版前用 --bigkeys 扫一遍新增缓存从源头卡住超大 value。所有缓存 key 必须有数据体量上限和 TTL。没有 TTL 的缓存要单独 review防止永远不删的大 key逐渐拖垮节点。这几条规则现在已经固化到团队的发布检查清单里之后的几次模型发版再也没有出现过类似问题。6. 缓存集群健康体检清单与排障经验沉淀6.1 一组可落地的巡检命令与频率这次故障让我意识到Redis 集群的巡检绝对不能只看存活状态和内存使用率。以下是我现在每周会执行的健康检查清单直接照抄可用检查项命令/方式建议频率慢查询slowlog get 20逐个节点执行每天大 key--bigkeys -i 0.01逐个节点执行每周低峰热 key--hotkeys需 LFU 策略每周 活动前持久化 fork 耗时INFO persistence的 latest_fork_usec每天分片流量分布云监控或自建监控按节点看带宽/CPU实时内存淘汰与过期INFO memory关注 maxmemory 水位、evicted_keys实时巡检的核心思路很简单不要只看集群平均值一定要按分片/节点维度拆开看。热 key 和大 key 造成的问题平均值永远测不出来。6.2 容量规划不能只看内存要看分片的压力分布以前做 Redis 容量规划优先问的是内存够不够。这次故障告诉我内存是最容易满足的资源真正容易出瓶颈的是单分片的 CPU、网卡带宽和连接数。规划的时候我现在的算法是先统计特征缓存里最大的 value 体积比如 max 400KB 上限。再预估这个 key 的峰值 QPS。两者相乘得出单 key 需要的带宽预算。比如 400KB × 1000 QPS 400MB/s已经接近千兆网卡的一半了这种 key 必须做拆分或者副本分散。换句话说Redis 集群的扩容指标应该包含单分片带宽预算和CPU 预算而不只是用了多少 GB 内存。6.3 告警设计别等P99掉了才发现这次故障的告警只覆盖了应用侧 P99 和 Redis 节点平均 CPU导致故障发生后差不多 10 分钟才被感知。事后我调整了告警策略按分片维度增加 CPU、网卡带宽、连接数告警阈值分别是 70%、70%、80%。每个节点 slowlog 数量在 10 分钟内超过 N 条就告警。针对特征缓存的大 key用脚本定期扫描发现超过 512KB 的 value 直接推送告警到值班群。客户端侧增加 Redis 命令 P99 耗时监控超过 50ms 就触发联动告警。这些告警不一定能完全避免故障但一定能把发现时间从天级压缩到分钟级。6.4 排障顺序的反思先依赖、后自身最后聊一点个人体会。这次故障最浪费时间的地方就是一开始把精力全放在了模型侧。原因也很简单前一天刚发过新模型谁都觉得自己变更引入的问题可能性最大。但实际情况恰恰是模型版本只是让特征缓存的访问模式发生了变化真正的放大器在缓存集群。我现在处理线上问题时排障顺序固定为先看依赖组件的健康状态再看自身代码和近期变更。推理服务这种强依赖缓存的系统尤其要这样。如果 Redis 慢模型再快也无济于事。另外非常建议团队提前维护一张推理服务依赖图明确写出每个下游组件Redis、数据库、配置中心的正常延迟基线、吞吐基线、告警阈值。遇到故障时直接按图索骥可以省掉大量猜谜时间。这次故障之后我把依赖图和排查手册写进了团队 Wiki群里的发生了什么焦虑式提问明显少了很多。