1、问题描述

业务反馈，出现很多连接redis的read timed out的报错

2、问题分析及解决

由于redis是单线程处理的，所有redis接收到命令，都会进入到队列中，等待执行。

当客户端，由于等待时间过长，没有接收到server端返回的数据，就是出现超时的报错。

程序里，jedis客户端，默认的超时时间是2s。

所以，怀疑是redis端在执行缓慢的命令，超过了客户端能够等待的最大的时间。

那么，在redis服务端，命令执行过慢，会在慢日志中进行记录。

所以，查看慢日志

进入到redis客户端中，执行下面的命令

2.1、查看redis中设置的慢日志记录时间

这个参数的意思是，当在redis中执行的命令，超过这个时间，就会记录慢日志

10.1x.xxx.138:30001> config get slowlog-log-slower-than
"slowlog-log-slower-than"
"10000" 

查询结果：10000（微秒,us）= 10毫秒（ms）

表示，当redis中执行的命令，超过10毫秒的，就会被记录。

2.2、redis默认会记录多少条慢日志

xxxxxx:30001> config get slowlog-max-len
"slowlog-max-len"
"128"

查询结果是128条。也就是只会记录128条慢日志记录。

OK，参数已经都明白了，接下去看当前记录的redis的情况

2.3、查看慢日志

xxx:30001> slowlog get 128

如果get后面什么都不加，默认返回10条。

这里返回全部的128条。

将结果输出到一个文件里面，查看结果如下（列出部分数据）：

3965090    # slowlog的id
1700478020 # unix时间戳，
2999271    # 执行命令的时间，单位是微秒（us）
KEYS
xxcsdfADG:{${ds}_lock}:lock_idx_trans_pk_de*
?:0

3965089
1700478017
5182858
KEYS
xxcsdfDATA:{${ds}_lock}:lock_idx_trans_pk_de*
?:0

3965088
1700478012
3007463
KEYS
xxcsdfADG:{${ds}_lock}:lock_idx_trans_pk_ds*
xxxxx.141:46855

3965087
1700478009
5234263
KEYS
xxcsdfDATA:{${ds}_lock}:lock_idx_trans_pk_de*
?:0

3965086
1700478004
3038860
KEYS
xxcsdfADG:{${ds}_lock}:lock_idx_trans_pk_de*
xxxxx.141:46855

发现有执行，超过2秒的

3965089
1700478017
5182858   # 大于5秒 ，5182858微秒 = 51828毫秒 = 5秒
KEYS
xxcsdfDATA:{${ds}_lock}:lock_idx_trans_pk_de*
?:0

这样就找到执行慢的语句了。

具体的执行时间，可以将时间戳进行转换

[root@xxcsdfztsjb-node-01 ~]# date -d @1700478017
Mon Nov 20 19:00:17 CST 2023
[root@xxcsdfztsjb-node-01 ~]# 

然后，接下来，就基于这个语句让研发继续查就好了。

2.4、慢日志记录顺序说明

redis默认记录128条，慢日志，序号 从1到128.

当超过128条的时候，第一条会被首先覆盖掉，然后以此类推。

也就是说：

执行slowlog get 128时，最上面的记录是最新的。

这一点，也可以通过unix时间戳转换工具来进行查看和验证。