背景
redis虽说是一个基于内存的KV数据库，以高性能著称，但是依然存在一些耗时比较高的命令，比如keys *，lrem等，更有甚者会在lua中写一些比较耗时的操作，比如大循环里面执行命令等，鉴于此，本篇将从源码角度分析redis慢日志的记录原理，并给出一些自己的看法。
环境说明
win10+redis v2.8.9，对本地调试redis源码感兴趣的可以参考我另一篇文章redis源码学习之工作流程初探。
redis执行命令流程
在这里就不重复redis的执行流程了，不清楚的可以参考我之前的文章redis源码学习之工作流程初探，这里重点说一下6.1，这一步是真实执行redis命令的地方，redis记录慢日志也是这一步实现的。
记录slowlog源码分析
1.执行redis 命令之前获取当前时间；
2.执行redis 命令之后计算耗时；
3.如果开启了记录slowlog而且耗时大于设置的阈值就将slowlog记录下来；
4.如果slowlog数目大于了设置的最大记录数，就移除最早插入的slowlog；
redis.c
/* Call() is the core of Redis execution of a command */
void call(redisClient *c, int flags) {
...
/* Call the command. */
c->flags &= ~(REDIS_FORCE_AOF|REDIS_FORCE_REPL);
redisOpArrayInit(&server.also_propagate);
dirty = server.dirty;
//执行命令前获取当前时间
start = ustime();
//执行命令对应的commandProc
c->cmd->proc(c);
//命令执行完成计算耗时，单位为ms
duration = ustime()-start;
dirty = server.dirty-dirty;
//记录slowlog
if (flags & REDIS_CALL_SLOWLOG && c->cmd->proc != execCommand)
slowlogPushEntryIfNeeded(c->argv,c->argc,duration);
}
slowlog.c
/* Push a new entry into the slow log.
* This function will make sure to trim the slow log accordingly to the
* configured max length. */
void slowlogPushEntryIfNeeded(robj **argv, int argc, long long duration) {
//如果slowlog_log_slower_than 小于0，说明不需要记录
if (server.slowlog_log_slower_than < 0) return; /* Slowlog disabled */
//耗时大于 slowlog_log_slower_than,说明需要记录，
//slowlog_log_slower_than默认为10ms
if (duration >= server.slowlog_log_slower_than)
listAddNodeHead(server.slowlog,slowlogCreateEntry(argv,argc,duration));
//slowlog记录数大于slowlog_max_len，就移除最早的那条slowlog
/* Remove old entries if needed. */
while (listLength(server.slowlog) > server.slowlog_max_len)
listDelNode(server.slowlog,listLast(server.slowlog));
}
/* Create a new slowlog entry.
* Incrementing the ref count of all the objects retained is up to
* this function. */
slowlogEntry *slowlogCreateEntry(robj **argv, int argc, long long duration) {
slowlogEntry *se = zmalloc(sizeof(*se));
int j, slargc = argc;
if (slargc > SLOWLOG_ENTRY_MAX_ARGC) slargc = SLOWLOG_ENTRY_MAX_ARGC;
//参数数量
se->argc = slargc;
//具体参数
se->argv = zmalloc(sizeof(robj*)*slargc);
for (j = 0; j < slargc; j++) {
/* Logging too many arguments is a useless memory waste, so we stop
* at SLOWLOG_ENTRY_MAX_ARGC, but use the last argument to specify
* how many remaining arguments there were in the original command. */
if (slargc != argc && j == slargc-1) {
se->argv[j] = createObject(REDIS_STRING,
sdscatprintf(sdsempty(),"... (%d more arguments)",
argc-slargc+1));
} else {
/* Trim too long strings as well... */
if (argv[j]->type == REDIS_STRING &&
argv[j]->encoding == REDIS_ENCODING_RAW &&
sdslen(argv[j]->ptr) > SLOWLOG_ENTRY_MAX_STRING)
{
sds s = sdsnewlen(argv[j]->ptr, SLOWLOG_ENTRY_MAX_STRING);
s = sdscatprintf(s,"... (%lu more bytes)",
(unsigned long)
sdslen(argv[j]->ptr) - SLOWLOG_ENTRY_MAX_STRING);
se->argv[j] = createObject(REDIS_STRING,s);
} else {
se->argv[j] = argv[j];
incrRefCount(argv[j]);
}
}
}
//发生时间
se->time = time(NULL);
//耗时
se->duration = duration;
//slowlog id，server.slowlog_entry_id自增
se->id = server.slowlog_entry_id++;
return se;
}
制造一条slowlog
为了讲解方便我使用断点的方式制造一条slowlog，方式如下：
1.连接redis，执行get 1；
2.ide 断点在redis.c 的Call函数c->cmd->proc处
3.等待10s+以后继续执行，即可产生一条例slowlog；
4.查看slowlog
127.0.0.1:6379> slowlog get
1) 1) (integer) 0 #slowlog 标识，从0开始递增
2) (integer) 1606033532 #slowlo*生时间，unix时间戳格式
3) (integer) 28049157 #执行命令耗时
4) 1) "get" # 执行的命令
2) "1"
slowlog分析
通过前面的章节对slowlog的写入过程有了一个初步的了解，其中有这么几点我要重点提一下：
1.slowlog如何开启
slowlog默认情况下是开启的，主要受限于slowlog-log-slower-than的设置，如果其大于0意味着开始slowlog，默认值为10ms，可以通过修改redis配置文件或者使用CONFIG SET这种方式，单位为微秒；
2.slowlog数量限制
默认情况下只会存储128条记录，超过128会丢弃最早的那条记录，可以通过修改redis配置文件或者使用CONFIG SET slowlog-max-len这种方式；
3.slowlog中的耗时的含义
耗时只包括执行命令的时间，不包括等待、网络传输的时间，这个不难理解，从redis的工作模型可知，redis执行命令采用单线程方式，所以内部有排队机制，如果之前的命令非常耗时，只会影响redis整体的吞吐量，但不一定会影响当前命令的执行时间，比如client执行一条命令整体耗时20s，但是slowlog记录的耗时只有10s；
4.slowlog中时间戳的含义
切记这个时间戳是redis产生slowlog的时间，不是执行redis命令的时间。
自己的一些思考
如果开发人员反馈redis响应变慢了，我们应该从哪些方面去排查呢？
1.查看slowlog分析是否有慢查情况，比如使用使用了keys *等命令；
2.slowlog中没有慢日志，可以结合应用程序中一些埋点来分析，可能是网络问题，找运维协助查看网络是否丢包、带宽是否被打满等问题；
3.如果排除网络问题，那可能是redis机器本身负载过高，排查内存、swap、负载等情况；
4.任何以高性能著称的组件都不是银弹，使用时一定要了解其api，比如keys命令，作者已经明确的说了其时间复杂度为O(N)数据量大时会有性能问题。
推荐阅读
Redis常见延迟问题排查手册
redis源码学习之工作流程初探