背景

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处
redis源码学习之slowlog-LMLPHP
3.等待10s+以后继续执行,即可产生一条例slowlog;

4.查看slowlog

 127.0.0.1:6379> slowlog get

1) 1) (integer) 0      #slowlog 标识,从0开始递增

   2) (integer) 1606033532  #slowlog产生时间,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源码学习之slowlog-LMLPHP

推荐阅读

Redis常见延迟问题排查手册
redis源码学习之工作流程初探

 
 

11-23 00:38