1

1. 现象

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

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

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

2. 排查

2.1. 查监控平台:接口速度

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

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

  1. 在那段时间前后,该接口都很正常,所以应该只是那段时间发生了什么。
  2. 不只是那一个接口超过300ms了,其实那段时间内,也有个别其他接口超过阈值。只不过因为那个接口的并发比较高,很明显的被告警机制检测出来。

2.2. 查监控平台:全链路日志

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

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

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

2.3. 分析代码

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

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

2.4. 查监控平台:redis连接池

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

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

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

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

2.5. 运维:查redis慢请求

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

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

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

2.6. 场景还原

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

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

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

3. 解决

3.1. 解决

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

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

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

3.2. 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

3.3. 其他

因为Spring中 Lettuce 连接池的bug,公司要求都改回 Jedis 连接池。感觉在该问题的避免上,Jedis 连接池应该也有优化空间。待后续实践后再分享。


KerryWu
641 声望159 粉丝

保持饥饿