引言

Redis在2.8.13版本引入了Latency Monitoring功能，用于以秒为粒度监控各种事件的发生频率，虽然在设计上我个人认为有一点小问题，但是其不失为一种很好的性能监测工具。

Latency功能提供了几个命令查看取得的数据，我注意到无论是官网文档还是博客其实几乎没有人详细的介绍这几个命令，所以有了这篇文章，但只说命令实在是没有意思，所以干脆把这篇文章写成介绍 Latency Monitoring 功能吧。本片文章从两个角度出发介绍Redis Latency Monitoring 功能，即Latency记录哪些事件与Latency涉及到的命令的详细作用。

本篇文章分析基于redis 6.2.3。

触发事件

官网的描述并不全面，花了点时间从最新版本的代码中找了下，现在触发延迟采样的有以下事件：

aof-write-pending-fsync：这里代码注释中写的很明确，即当后台的fsync正在执行的时候会使得write操作阻塞，所以在写入之前需要检查下BIO中是否有fsync任务pending，如果有的话就需要记录这个事件了。
aof-write-active-child：如果有子进程正在执行RDB写入，AOF重写或者在 Load module时启动一些side process，此时AOF write可能会慢一些。
aof-write-alone：一次正常的AOF write的延迟
aof-write：以上三种情况在每次AOF成功时一定会记录一种。这种事件就是一个AOF写入的均值，每次AOF成功记录一次，所以AOF成功时会记录两个事件，前三个中的一个和第四个。
aof-rewrite-write-data-to-child：用于AOF重写结束后向aof_pipe_write_data_to_child管道中发送重写期间接受到到命令的缓存。
aof-fsync-always：用于在策略为always时记录aof fsync的延迟，值得一提的是every second策略并没有被记录。
aof-fstat：fstat的时延统计
aof-rewrite-diff-write：子进程AOF重写结束以后向主进程发送信号，主进程的信号处理函数backgroundRewriteDoneHandler中会把aof_rewrite_buf_blocks的数据写入临时AOF文件然后改名。可能有同学很奇怪为什么8和5都重写了缓存了，原因在注释中写的很清楚（We send pieces of our AOF differences buffer so that the final write when the child finishes the rewrite will be small.）
aof-rewrite-done-fsync：同样是上面那个信号处理函数，记录其中AOF策略为always时fsync的时延，而everysecond时fsync被扔到BIO了。
aof-rename：还是上面那个信号处理函数，记录rename的时延
command-unblocking：这个板块比较麻烦，暂时没有时间看，但是干的事情就是在server完成了一些阻塞操作的时候进行记录，代码位于block.c中。调用过程为handleClientsBlockedOnKeys->serveClientsBlockedOnListKey->serveClientBlockedOnList。
active-defrag-cycle：redis增量内存碎片整理过程消耗的时间。这里暂时也没时间去看，代码位于defrag.c，函数为activeDefragCycle。
eviction-cycle：实际总内存用量大于server.maxmemory时进行内存驱逐，策略加上不驱逐一共有七种。值得一提的是AOF buffers 以及slaves output buffers 并没有被算在已经使用的内存中。整个performEvictions的时间被这一项计算。
eviction-del：仅仅是删除键这一步所花费的时间，lazyfree被记录的时间是放入计算以及放入BIO队列的整个时间，而不是直到键真正的被释放。
rdb-unlink-temp-file：BGSAVE的过程是这样的，子进程把数据写入临时文件，结束的话向父进程发送信号；父进程接收到信号以后更新属性，然后改名，覆盖原来的dump.rdb。这样如果子进程创建RDB被中断以后需要来删除这个临时的RDB文件，文件格式是temp-pid-.rdb。
while-blocked-cron：调用链为processEventsWhileBlocked->whileBlockedCron，这里是用在进程阻塞在一些不可中断的操作时不时处理一些事件。processEventsWhileBlocked其实就是跑事件循环，注意其只注册了AE_FILE_EVENTS，其等同于AE_READABLE，所以accept，read，write，close操作其实都可以被处理，时间事件没有被注册。
fast-command：在命令表中第四项的描述中有fast标记在call被调用时都是被记录在fast-command中
command：当然不是fast-command的就是command了。
fork：fork执行后在Parent中记录时延。server.stat_fork_rate参数很有意思，记录了fork时每秒拷贝的内存数，单位GB/S。

命令解析

目前官网的命令有一下几种：

LATENCY LATEST - returns the latest latency samples for all events.
LATENCY HISTORY - returns latency time series for a given event.
LATENCY RESET - resets latency time series data for one or more events.
LATENCY GRAPH - renders an ASCII-art graph of an event’s latency samples.
LATENCY DOCTOR - replies with a human-readable latency analysis report.

首先我们明确下 Latency Monitoring 的数据结构以及运行原理，然后看看命令的实际作用。

基础的数据结构非常简单：

#define LATENCY_TS_LEN 160 /* History length for every monitored event. */

struct latencySample {
   
    int32_t time; /* We don't use time_t to force 4 bytes usage everywhere. */
    uint32_t latency; /* Latency in milliseconds. */
};

/* The latency time series for a given event. */
struct latencyTimeSeries {
   
    int idx; /* Index of the next sample to store. */
    uint32_t max; /* Max latency observed for this event. */
    struct latencySample samples[LATENCY_TS_LEN]; /* Latest history. */
};

/* Latency statistics structure. */
struct latencyStats {
   
    uint32_t all_time_high; /* Absolute max observed since latest reset. */
    uint32_t avg;           /* Average of current samples. */
    uint32_t min;           /* Min of current samples. */
    uint32_t max;           /* Max of current samples. */
    uint32_t mad;           /* Mean absolute deviation. */
    uint32_t samples;       /* Number of non-zero samples. */
    time_t period;          /* Number of seconds since first event and now. */
};

所有埋点的地方都调用latencyAddSampleIfNeeded，比如latencyAddSampleIfNeeded("aof-rewrite-write-data-to-child",latency);

/* Add the sample only if the elapsed time is >= to the configured threshold. */
#define latencyAddSampleIfNeeded(event,var) \
    if (server.latency_monitor_threshold && \
        (var) >= server.latency_monitor_threshold) \
          latencyAddSample((event),(var));

实际执行计算的函数是latencyAddSample，我们就不看代码了，其就是通过event这个字符串在字典server.latency_events中创建一个latencyTimeSeries数据项，然后跑一些计算。

我们一个命令一个命令看

history

if (!strcasecmp(c->argv[1]->ptr,"history") && c->argc == 3) {
   
        /* LATENCY HISTORY <event> */
        ts = dictFetchValue(server.latency_events,c->argv[2]->ptr);
        if (ts == NULL) {
   
            addReplyArrayLen(c,0);
        } else {
   
            latencyCommandReplyWithSamples(c,ts);
        }
    }

这个没啥说的，就是在字典中根据event取latencyTimeSeries结构，然后apply。也就是返回一个事件所有的记录。

latest

 else if (!strcasecmp(c->argv[1]->ptr,"latest") && c->argc == 2) {
   
        /* LATENCY LATEST */
        latencyCommandReplyWithLatestEvents(c);
    } 

void latencyCommandReplyWithLatestEvents(client *c) {
   
    dictIterator *di;
    dictEntry *de;

    addReplyArrayLen(c,dictSize(server.latency_events));
    di = dictGetIterator(server.latency_events);
    while((de = dictNext(di)) != NULL) {
   
        char *event = dictGetKey(de);
        struct latencyTimeSeries *ts = dictGetVal(de);
        int last = (ts->idx + LATENCY_TS_LEN - 1) % LATENCY_TS_LEN;

        addReplyArrayLen(c,4);
        addReplyBulkCString(c,event);
        addReplyLongLong(c,ts->samples[last].time);
        addReplyLongLong(c,ts->samples[last].latency);
        addReplyLongLong(c,ts->max);
    }
    dictReleaseIterator(di);
}

可以看到是返回每个事件的最新一条记录。

reset

 else if (!strcasecmp(c->argv[1]->ptr,"reset") && c->argc >= 2) {
   
        /* LATENCY RESET */
        if (c->argc == 2) {
   
            addReplyLongLong(c,latencyResetEvent(NULL));
        } else {
   
            int j, resets = 0;

            for (j = 2; j < c->argc; j++)
                resets += latencyResetEvent(c->argv[j]->ptr);
            addReplyLongLong(c,resets);
        }
    }

int latencyResetEvent(char *event_to_reset) {
   
    dictIterator *di;
    dictEntry *de;
    int resets = 0;

    di = dictGetSafeIterator(server.latency_events);
    while((de = dictNext(di)) != NULL) {
   
        char *event = dictGetKey(de);

        if (event_to_reset == NULL || strcasecmp(event,event_to_reset) == 0) {
   
            dictDelete(server.latency_events, event);
            resets++;
        }
    }
    dictReleaseIterator(di);
    return resets;
}

删除某个或者所有事件全部的记录。

graph

样例直接查看官网样例即可：https://redis.io/commands/latency-graph

可以看到这个图像十分让人头大，直接看根本不知所以然，其实这玩意就是用sparkline.c画的，显示一个大致的数据走向。

比如[ 1,2,3,4,5,6,7,8,9,10,10,8,5,3,1] 显示

       _o##_   
     _#|||||   
   o#|||||||#  
_o#||||||||||#_

调用函数为sds latencyCommandGenSparkeline(char *event, struct latencyTimeSeries *ts)，每个图描述某一个数据项的数据走势。

doctor

只能说是一个很有意思的功能，但是并没有什么用。触发什么事件就返回什么字符串，一个映射关系。

一些有意思的点

发现AOF中一个很有意思的点，如下：

    if (sdslen(server.aof_buf) == 0) {
   
        /* Check if we need to do fsync even the aof buffer is empty,
         * because previously in AOF_FSYNC_EVERYSEC mode, fsync is
         * called only when aof buffer is not empty, so if users
         * stop write commands before fsync called in one second,
         * the data in page cache cannot be flushed in time. */
        if (server.aof_fsync == AOF_FSYNC_EVERYSEC &&
            server.aof_fsync_offset != server.aof_current_size &&
            server.unixtime > server.aof_last_fsync &&
            !(sync_in_progress = aofFsyncInProgress())) {
   
            goto try_fsync;
        } else {
   
            return;
        }
    }

在检测到AOF缓冲区等于零的时候需要经过一系列的条件判断是否要跳到try_fsync处，那个标签就是执行fsync的地方。为什么要这么写，我个人认为原因是有可能在stopAppendOnly中。

void stopAppendOnly(void) {
   
    serverAssert(server.aof_state != AOF_OFF);
    flushAppendOnlyFile(1);
    if (redis_fsync(server.aof_fd) == -1) {
   
        serverLog(LL_WARNING,"Fail to fsync the AOF file: %s",strerror(errno));
    } else {
   
        server.aof_fsync_offset = server.aof_current_size;
        server.aof_last_fsync = server.unixtime;
    }
    close(server.aof_fd);

    server.aof_fd = -1;
    server.aof_selected_db = -1;
    server.aof_state = AOF_OFF;
    server.aof_rewrite_scheduled = 0;
    killAppendOnlyChild();
    sdsfree(server.aof_buf);
    server.aof_buf = sdsempty();
}

如果此时fsync失败，缓冲区照样会被置为空，但是内存中这部分数据还是没有被刷新到磁盘，此时就有了上面那个奇怪的判断。即server.aof_fsync_offset != server.aof_current_size且sdslen(server.aof_buf) == 0。

总结

一个redis中实用的功能，但是实战性较差，因为一种事件一秒最多记录一次，而且必须设定初始阈值才可以。假设阈值100ms，99ms的事件仍然会出现毛刺，但是却不会被记录。但是开源的东西嘛，又不是不能用。

参考：