问题描述

某产品线应用访问Redis出现超时（超时时间配置的是2000ms），异常信息：

分析过程

查看监控数据

通过监控数据，了解应用运行状态以确定应用出现问题时间点、是否过载、依赖服务是否过载等基本信息。

系统监控指标

CPU、内存、Load、磁盘指标数据都是正常的，所以系统资源是足够的。

JVM监控指标

FullGC过于频繁及耗时较长的情况下会造成应用阻塞住，从图中看FullGC发生的频次是正常的，一次FullGC耗时也是正常的，所以FullGC不是造成SocketTimeoutException的原因。

Redis监控指标

从Redis控制台及阿里云杜康上该Redis实例的CPU使用率、内存使用率等指标都是正常的。

分析应用异常

分析异常日志，首先需要弄明白的是应用抛异常时候执行的业务逻辑及异常本身含义；异常在本机出现的频次情况，是否存在规律性；及异常在该应用的集群上的规律性。

除了访问Redis异常，应用依赖得其他服务没有超时情况。

单机异常规律

分析了每小时、每分钟及每秒钟异常出现的次数，发现异常具有一定周期性：每个小时在固定的几个时间点会集中出现，出现的时候会集中在相邻的几秒钟内。

集群异常规律

统计了应用集群中其他机器的异常规律，每台机器出现异常的规律是一致的：不出现都不出现，要出现一起出现。

统计超时的key

我们统计了异常日志中，所有超时的key，然后单独访问这些key，并没有任何发生超时的情况。

初步结论

通过上面的分析，很有可能是应用侧在相对集中的时间点访问了同一个Redis节点，在该Redis节点产生了慢查询，进而阻塞掉了正常的请求Redis的命令。

验证结论

访问Redis链路

slowlog

最先想到是Redis慢查询，有些应用卡慢的场景到这里可以找到线索，遗憾的是slowlog并没有看到应用端发过来的命令。

Redis单节点info all

接着是Redis单节点的监控指标，一些CPU高、卡慢的场景在这里找到线索，经过对比确实有个节点avgRT比其他节点高很多。下面是两个不同节点的数据：

avgRT=45的是节点8，初步判定节点8是问题节点。

定位redis节点

我们初步判定节点8是问题节点，超时的key是否打到了这个节点呢？阿里云redis自研了info key指令：查询key所属的slot和db。

可惜的是这个版本的Redis返回的node_index跟控制台上实例拓扑图的node index不一致。

我们只好去每个Redis节点通过tcpdump抓包，对抓包里的key执行info key <biz_key>来核对node_index:5到底是哪个节点，最终定位到了超时key都是打在了节点13.

定位异常key

是对哪些key的访问阻塞住了Redis，进而造成其他命令的超时呢？首先想到的是大key的影响。

bigkeys

tcpdump定位大key影响

• 在redis节点132进行tcpdump抓包且过滤大key

tcpdump -i any tcp and dst port 3048 -A -nn | grep -E '大key1|大key2|大key3|......'

• 在应用侧过滤日志中的异常信息

tail -f error.log | grep 'SocketTimeoutException'

当应用侧出现SocketTimeoutException的时候，redis节点上的key是需要我们引起关注的，最后将定位的key提供给研发。

经验总结

排查此类问题，几个需要关注的点

• 统计超时key，及key对应的redis节点
• Redis slowlog慢查询
• Redis单节点info all指标对比不同节点服务情况
• Redis bigkeys
• 还有一个注意的点是Redis hotkeys