• 背景
• 環境說明
• redis執行命令流程
• 記錄slowlog原始碼分析
• 製造一條slowlog
• slowlog分析
  • 1.slowlog如何開啟
  • 2.slowlog數量限制
  • 3.slowlog中的耗時的含義
  • 4.slowlog中時間戳的含義
• 自己的一些思考

背景

redis雖說是一個基於記憶體的KV資料庫，以高效能著稱，但是依然存在一些耗時比較高的命令，比如keys *，lrem等，更有甚者會在lua中寫一些比較耗時的操作，比如大迴圈裡面執行命令等，鑑於此，本篇將從原始碼角度分析redis慢日誌的記錄原理，並給出一些自己的看法。

環境說明

win10+redis v2.8.9，對本地除錯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  #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)資料量大時會有效能問題。

推薦閱讀