redis中查看慢日志以及返回参数值的解释

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时间戳转换工具来进行查看和验证。