redis 性能问题查找

          使用redis作为数据库时，系统出现少量超时，通过日志信息发现，超时发生在bgsave时。bgsave命令会fork一个子进程，子进程会将redis数据库信息dump到rdb文件中。因此不能确定使用bgsave命令时，是fork一个子进程引起超时，还是dump文件时与主进程的sync同步同时写磁盘引起的超时。

         这时就可以使用redis自带的showlog命令了，但是需要在redis 配置文件中加入showlog使用的参数。

################################## SLOW LOG ###################################

# The Redis Slow Log is a system to log queries that exceeded a specified
# execution time. The execution time does not include the I/O operations
# like talking with the client, sending the reply and so forth,
# but just the time needed to actually execute the command (this is the only
# stage of command execution where the thread is blocked and can not serve
# other requests in the meantime).
# 
# You can configure the slow log with two parameters: one tells Redis
# what is the execution time, in microseconds, to exceed in order for the
# command to get logged, and the other parameter is the length of the
# slow log. When a new command is logged the oldest one is removed from the
# queue of logged commands.

# The following time is expressed in microseconds, so 1000000 is equivalent
# to one second. Note that a negative number disables the slow log, while
# a value of zero forces the logging of every command.
#如果一个命令执行操作10ms，需要记录下这个命令和执行时间
slowlog-log-slower-than 10000

# There is no limit to this length. Just be aware that it will consume memory.
# You can reclaim memory used by the slow log with SLOWLOG RESET.
#保留最近的1024个超时的命令
slowlog-max-len 1024

             下面开始使用showlog查看超时的命令有哪些，先使用redis-cli连接服务器，在使用showlog命令查看超时的命令有哪些。

redis 127.0.0.1:7771> SLOWLOG GET 3
1) 1) (integer) 174
   2) (integer) 1413914462
   3) (integer) 724446
   4) 1) "bgSave"
2) 1) (integer) 173
   2) (integer) 1413828062
   3) (integer) 740908
   4) 1) "bgSave"
3) 1) (integer) 172
   2) (integer) 1413741662
   3) (integer) 737333
   4) 1) "bgSave"

            问题发现了，bgsave命令执行时间用了700多ms，原来是fork时使用了太长时间，从而阻塞了主进程。

-------------------------------------------------showlog命令实现细节------------------------------------------------------

           执行时间的记录。所有redis命令都会调用call函数来执行，而call函数就在执行前后记录下时间，并放在showlog时间队列中，队列的最大长度就是配置文件定义的长度。

/* Call() is the core of Redis execution of a command */
void call(redisClient *c, int flags) {
    long long dirty, start, duration;
    int client_old_flags = c->flags;

   。。。
    /* Call the command. */
    c->flags &= ~(REDIS_FORCE_AOF|REDIS_FORCE_REPL);
    redisOpArrayInit(&server.also_propagate);
    dirty = server.dirty;
    start = ustime();   //记录命令执行开始时间
    c->cmd->proc(c);    //执行命令
    duration = ustime()-start;   //记录命令执行时间
    dirty = server.dirty-dirty;

    /* When EVAL is called loading the AOF we don't want commands called
     * from Lua to go into the slowlog or to populate statistics. */
    if (server.loading && c->flags & REDIS_LUA_CLIENT)
        flags &= ~(REDIS_CALL_SLOWLOG | REDIS_CALL_STATS);

    /* If the caller is Lua, we want to force the EVAL caller to propagate
     * the script if the command flag or client flag are forcing the
     * propagation. */
    if (c->flags & REDIS_LUA_CLIENT && server.lua_caller) {
        if (c->flags & REDIS_FORCE_REPL)
            server.lua_caller->flags |= REDIS_FORCE_REPL;
        if (c->flags & REDIS_FORCE_AOF)
            server.lua_caller->flags |= REDIS_FORCE_AOF;
    }

    /* Log the command into the Slow log if needed, and populate the
     * per-command statistics that we show in INFO commandstats. */
    if (flags & REDIS_CALL_SLOWLOG && c->cmd->proc != execCommand)
        slowlogPushEntryIfNeeded(c->argv,c->argc,duration);   //保存命令执行时间
     。。。
}

          执行时间的查看。slowlogCommand函数对应showlog命令。

/* The SLOWLOG command. Implements all the subcommands needed to handle the
 * Redis slow log. */
void slowlogCommand(redisClient *c) {
    if (c->argc == 2 && !strcasecmp(c->argv[1]->ptr,"reset")) {
        slowlogReset();
        addReply(c,shared.ok);
    } else if (c->argc == 2 && !strcasecmp(c->argv[1]->ptr,"len")) {
        addReplyLongLong(c,listLength(server.slowlog));
    } else if ((c->argc == 2 || c->argc == 3) &&
               !strcasecmp(c->argv[1]->ptr,"get"))
    {
        long count = 10, sent = 0;
        listIter li;
        void *totentries;
        listNode *ln;
        slowlogEntry *se;

        if (c->argc == 3 &&
            getLongFromObjectOrReply(c,c->argv[2],&count,NULL) != REDIS_OK)
            return;

        listRewind(server.slowlog,&li);
        totentries = addDeferredMultiBulkLength(c);
        //打印count数量的超时命令
        while(count-- && (ln = listNext(&li))) {
            int j;

            se = ln->value;
            addReplyMultiBulkLen(c,4);
            addReplyLongLong(c,se->id);
            addReplyLongLong(c,se->time);
            addReplyLongLong(c,se->duration);
            addReplyMultiBulkLen(c,se->argc);
            for (j = 0; j < se->argc; j++)
                addReplyBulk(c,se->argv[j]);
            sent++;
        }
        setDeferredMultiBulkLength(c,totentries,sent);
    } else {
        addReplyError(c,
            "Unknown SLOWLOG subcommand or wrong # of args. Try GET, RESET, LEN.");
    }
}