背景
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 #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常見延遲問題排查手冊
redis原始碼學習之工作流程初探
