万恶的Scan，30万单就这样没了...
<p>昨天晚上下班回家，在地铁上，老大突然打来电话，B 系统生产环境响应缓慢，影响了 A 系统的使用，几万小哥收不了单，大概有 30 万单卡住了，你去帮忙定位一下。</p><p> </p>
<p>我 8 点半左右到家，立马上线入会......</p>
<p><strong>重启</strong></p>
<p>我入会的时候，已经有同事在帮忙定位了，俗话说的好，重启能解决 80% 的问题，如果重启解决不了，那肯定是重启的次数还不够，呸，不对，重启解决不了，就真的要去定位了。</p>
<p>事实证明，重启后走一波压测依然没什么用，1000 个并发，平均响应时间在 3~4 秒，连续压了几次都是这样的结果。</p>
<p><strong>升级配置</strong></p>
<p>重启看来是无效了，进入第二个阶段——升级配置，2 台 4 核 8G 的实例升级到 6 台 8 核 16G，数据库的配置也翻了一倍，能用钱解决的问题，我们一般不会投入太多的人力!</p>
<p>事实证明，加配置也没什么卵用，1000 个并发，压测的平均响应时间还是在 3~4 秒。</p>
<p>有点意思，此时，我介入了。</p>
<p><strong>查看监控</strong></p>
<p>我上线之后，查看了一下监控，实例的 CPU、内存、磁盘、网络 IO、JVM 堆内存使用情况好像都没啥问题，这真是个头疼的问题。</p>
<p><strong>本地压测</strong></p>
<p>我们分成两波同学，一波去准备本地压测，一波继续分析，经过本地压测，我们发现，本地环境，单机，1000 个并发，妥妥的，毛问题都没有，平均响应基本维持在几百毫秒。</p>
<p>看来，确实跟服务本身没有问题。</p>
<p><strong>代码走查</strong></p>
<p>实在没有办法了，拿出代码，一群大老爷们一起看代码，研发同学给我们讲解业务逻辑，当然，他已经被各位大佬给骂死了，写的什么破代码。</p>
<p>其实，在我介入之前，他们已经改过一波代码了，有个地方把 redis 命令 scan 改成了 keys *，这里埋了个坑，但是，现在不是主要问题，后面我们会说。</p>
<p>代码一路走读下来，发现有很多的 redis 操作，还有个 for 循环里面在调 redis 的 get 命令，其他的都是常规的数据库操作，而且都加了索引的。</p>
<p>所以，初步排查，数据库这里应该是没有什么问题，主要问题可能还是集中在 redis 这块，调用太频繁了。</p>
<p><strong>加日志</strong></p>
<p>代码走查下来，除了那个 scan 改成了 keys *(这个我还不知道)，基本上没有什么问题，加日志吧， 一小段一小段的加上日志，OK，重启服务，压测来一波。</p>
<p>当然了，结果没有什么变化，分析日志。</p>
<p>通过日志，我们发现，调用 redis 的时候时而很快，时而很慢，看起来像是连接池不够的样子，也就是一批请求先行，一批请求在等待空闲的 redis 连接。</p>
<p><strong>修改 redis 连接数</strong></p>
<p>查看 redis 配置，用的是单机模式，1G 内存， 连接数默认的 8，客户端还是比较老的 jedis，果断改成 springboot 默认的 lettuce，连接数先调整为 50，重启服务，压一波。</p>
<p>平均响应时间从 3~4 秒降到了 2~3 秒，并不明显，继续加大连接数，因为我们是 1000 个并发，每个请求都有很多次 redis 操作，所以，肯定会有等待，这次我们把连接数直接干到了 1000，重启服务，压一波。</p>
<p>事实证明，并没有明显地提升。</p>
<p><strong>再次查看日志</strong></p>
<p>此时，已经没有什么好的解决办法了，我们再次回到日志中，查看 redis 相关操作的时间，发现 99% 的 get 操作都是很快返回的，基本上是在 0~5 毫秒之间，但是，总有那么几个达到了 800~900 毫秒才返回。</p>
<p>我们以为 redis 这块没什么问题了。但是，压测了好几次，时间一直提不上去。</p>
<p>很无奈了，此时，已经半夜 3 点多了，领导发话，把 XX 云的人喊起来。</p>
<p><strong>云排查</strong></p>
<p>最后，我们把 XX 云相关的人员喊起来一起排查问题，当然，他们是不情愿的，但是，谁让我们给钱了呢!</p>
<p>XX 云的负责人，把 redis 的专家搞起来，帮我们看了下 redis 的指标，最后，发现是 redis 的带宽满了，然后触发了限流机制。</p>
<p>他们临时把 redis 的带宽增大三倍，让我们再压测一波。握了颗草，平均响应时间一下子降到了 200~300 毫秒!!!!</p>
<p>真的是握了颗草了，这就有点坑了，你限流就算了，带宽满了也不报警一下的么......</p>
<p>这真是个蛋疼的问题。到这里，我们以为问题就这样解决了，领导们也去睡觉了!</p>
<p><strong>上生产</strong></p>
<p>既然问题原因找到了，那就上生产压一波吧!我们让 XX 云的专家把生产的带宽也增大了三倍大小。</p>
<p>从生产提交拉一个 hotfix 分支，关闭签名，重启服务，压测走一波。完蛋，生产环境更差，平均响应时间在 5~6 秒。</p>
<p>测试环境我们是改了连接池配置的，生产环境还是 jedis，改之，走一波。并没有什么实际作用，还是 5~6 秒。</p>
<p>真是个蛋疼的问题。</p>
<p><strong>查看监控</strong></p>
<p>查看 XX 云中 redis 的监控，这次带宽、流控都是正常的。</p>
<p>这次不正常的变成了 CPU，redis 的 CPU 压测的时候直接飙到了 100%，导到应用响应缓慢。</p>
<p><strong>再次唤醒 XX 云 redis 专家</strong></p>
<p>已经凌晨四点多了，大家已经没什么思路了，XX 云的 redis 专家，你给我再起来!</p>
<p>再次唤醒 XX 云的 redis 专家，帮我们分析了下后台，发现 10 分钟内进行了 14 万次 scan......</p>
<p><strong>万恶的 scan</strong></p>
<p>询问研发人员哪里用到了 scan(前面他们改的，我不知道)，发现，每次请求都会调用 scan 去拿某个前缀开头的 key，每次扫描 1000 条数据，查看 redis 键总数，大概有 11 万条。</p>
<p>也就是说，一个请求就要 scan 100 次，1000 并发，大概就是 10 几万次 scan。</p>
<p>我们知道，redis 中 scan 和 keys * 是要进行全表扫描的，非常消耗 CPU，14 万次 scan 操作，直接让 CPU 上天了。</p>
<p><strong>为什么测试环境 CPU 没有上天呢?</strong></p>
<p>对比了下，测试环境和生产环境 redis 的键总数，测试环境只有 900 个 key，每次请求也就 scan 一次或者 keys * 一次，毛线问题都没有。</p>
<p>为什么生产环境有这么多 key?</p>
<p>询问研发人员，为什么生产环境有这么多 key，没有设置过期时间吗?</p>
<p>研发人员说设置了的，是另一个同事写的代码，打开代码，真是一段魔性的代码，具体代码我就不方便贴出来了，里面有根据条件判断要不要设置过期时间，经过分析，大部分情况下，都没有设置过期时间成功。</p>
<p><strong>当前解决办法</strong></p>
<p>此时，已经凌晨 4 点半了，虽然大家还很兴奋，但是，经过领导决策，暂时先不动了。</p>
<p>因为，目前 A 系统已经暂停调用 B 系统了，所以，此时 B 系统可以说流量几乎为 0 了。</p>
<p>我们白天再分两个阶段来修复这个问题：</p>
<ul>
<li>
<p>第一步，先清理掉生产环境 redis 的数据，只保留一小部分必要的数据。</p>
</li>
<li>
<p>第二步，修改 scan 某前缀开头的数据，改成 hash 存储，这样可以减少扫描的范围。</p>
</li>
</ul>
<p>好了，本次生产事故排查就到这里了。</p>
<p><strong>总结</strong></p>
<p>本次生产事件跟以往遇到的事件都略有不同，大概总结一下：</p>
<ul>
<li>
<p>以往都是应用服务本身的 CPU、内存、磁盘、JVM 这些问题，redis 的带宽和限流还是第一次遇见。</p>
</li>
<li>
<p>上了 XX 云以后，很多东西还没有弄得熟练，包括监控指标这些，还需要慢慢摸索。</p>
</li>
<li>
<p>redis 一定要禁用掉 keys 和 scan 命令，且大部分 key 应该设置过期时间!</p>
</li>
</ul>
<p>好了，本次事件大概就写这么多，后续有新的情况我也会继续跟进的，当然，最好不要有新的情况!</p>
<p>源文地址：https://developer.51cto.com/art/202103/648155.htm#topx</p>
页:
[1]