记一次Redis O(n)命令拖慢接口

1. 现象

某天突然收到运维告警消息，反馈产线有接口在某一段时间慢了，随之性能优化的JIRA任务也开过来了，大致内容如下：

API告警 - Base Tomcat Accesslog: 
微服务: xxxapi 
接口: /xxxx/xxx POST 
在 [ 2022/xx/xx 10:42:00 ~ 10:43:00 ] 时间窗口，RT > 阈值(300ms) 发生 141 次。

公司内部对API的响应时间要求是低于300ms，超过的都属于有性能问题的接口，接下来就排查吧。

首先就去查看公司的API监控平台，确认这个接口的确在这段时间的确在响应速度上，有100多次超过300ms。

不过发现几个有意思的现象：

虽然上面发现，可能不只是那一个接口的问题，但还是要仔细分析一下那个接口的全链路日志。

通过调用链路图，可以明显的发现，主要的耗时都在redis命令的执行阶段。又找了那段时间，其他的几个接口，结果都是一样的。

接下来就应该看看对应接口的代码，是不是执行redis命令时，有什么影响性能的问题。

找到对应接口的代码，代码中唯一用到redis的命令是 HMGET key field1 [field2] ，分析后排除该代码的问题：

代码中就那一次的redis调用，HMGET 不是耗时的命令（不在后文 O(n)命令之列），且 field 的数量是可枚举的，最多也就几十个，不会有多耗时。
该接口因为之前预计到并发高，所以上线之前经过压测，上万QPS完全不成问题，不会在这里栽跟头。

排除了代码层面上该接口的问题，那只能从运维侧看看执行redis命令慢的问题了，正好监控平台上有mysql、redis连接池的监控。不看不知道，一看吓一跳。

在出问题时间段，redis连接数瞬间飙升，直接超过了最大空闲连接数。在时间节点上，和产线出现慢响应的时间完全吻合。

可以推测出，这段时间可能执行了某些奇怪的命令，造成了redis阻塞，其他redis请求只能频繁的创建新的连接，从而导致redis连接池中连接数飙升。

想要推测那段时间redis经历了什么，只能托付于运维的同事了。

通过从运维同事导出来的，那段时间redis执行过的慢请求日志，果然和预想的一样。那段时间执行了大量的慢请求命令，尤其是一段 lrange 命令，每次执行时间都超过了300ms，一分钟执行了几百次。

通过具体的redis命令，倒推找到了对应的代码，该代码对应的其实是一段对应用户登录后，通过MQ异步刷新用户权限的逻辑。因为是异步消费，所以就算执行的慢，也并不会因为响应时间阈值而被告警。

再结合 ELK 中有关该接口的调用日志，可以还原出问题发生的完整过程。

该 lrange 命令单独执行还行，可那段时间在产线有大批量用户的登录并发，导致该慢请求命令阻塞住了redis，大量redis请求都在阻塞排队，redis连接池中连接数也在不断扩展。

所以说，那段时间所有的redis请求命令，都会因为阻塞而延迟执行完成。告警的那个接口属于“躺枪”，因为它调用的并发高，所以表现显著，被告警程序当典型抓住了。

如果没有这一步步排查，很难相信一个API的告警，是由于另外一个毫无关系的API影响的。

lrange 是时间复杂度为 O(n) 的命令，原则上是不应该被频繁调用的。分析代码上下文逻辑，其实只是为了全量存储和读取 List 类型数据。完全可以用redis中的 String 代替 List。

对于redis 中 keys * 、flushdb、flushall 等超耗时的命令，可以直接作为禁用命令，维护进 redis.conf的禁用命令清单中。

但像 lrange 这种可以用，但要严格审视应用场景的命令，就需要研发人员特别注意。下面整理了一下redis常见的 O(n) 命令。

String: MSET、MSETNX、MGET
List: LPUSH、RPUSH、LRANGE、LINDEX、LSET、LINSERT
Hash: HDEL、HGETALL、HKEYS/HVALS
Set: SADD、SREM、SRANDMEMBER、SPOP、SMEMBERS、SUNION/SUNIONSTORE、SINTER/SINTERSTORE、SDIFF/SDIFFSTORE
Sorted Set: ZADD、ZREM、ZRANGE/ZREVRANGE、ZRANGEBYSCORE/ZREVRANGEBYSCORE、ZREMRANGEBYRANK/ZREMRANGEBYSCORE