# 30 | 如何在系统中实现延迟监控？

    你好，我是蒋德钧。

我们知道，Redis的一个显著特征就是**能提供低延迟的数据访问**。而如果Redis在运行过程中变慢了，我们就需要有方法能监控到哪些命令执行变慢了。更进一步的需求，就是我们需要有方法监控到，是Redis运行过程中的哪些事件导致Redis变慢了。这样一来，我们就既可以检查这些慢命令，分析它们的操作类型和访问的数据量，进而提出应对方法，也可以检查监控记录的事件，分析事件发生的原因并提出应对方法。

那么，为了满足这些需求，我们就需要有一套监控框架，一方面能监测导致Redis变慢的事件，另一方面，能监控并记录变慢的命令。其实，这也是我们在开发后端系统时，经常会面临的一个运维开发需求，也就是**如何监控后端系统的运行状态**。

今天这节课，我就来带你了解Redis的延迟监控框架和慢命令日志的设计与实现。掌握今天的课程内容后，一方面，你可以把这套监控框架应用到实际的业务，而另一方面，你也可以参考Redis的实现，给自己的系统增加延迟监控功能。

下面，我们就先来看下Redis实现的延迟监控框架。

## 延迟监控框架的实现

实际上，Redis在运行过程中，以下表格中给出的几类事件都会导致Redis变慢，我们通常也把这些事件称为**延迟事件**。你可以参考表格中的这些事件类型，以及它们在源码中对应的事件名称。

![图片](https://static001.geekbang.org/resource/image/db/73/db2c320f4af71fdc2c941dd9c58fff73.jpg?wh=1920x908)

那么针对这些事件，Redis实现了延迟监控框架，通过采样的方式来记录它们的执行情况。当需要排查问题时，延迟监控框架提供了**latency history命令**，以便运维人员检查这些事件。

下面，我们就来看下记录事件执行情况的数据结构。因为延迟监控框架是在[latency.h](https://github.com/redis/redis/tree/5.0/src/latency.h)和[latency.c](https://github.com/redis/redis/tree/5.0/src/latency.c)文件中实现的，你也可以在这两个文件中找到相应的数据结构和函数。

### 记录事件执行情况的数据结构

首先，Redis是使用了**latencySample结构体**，来记录延迟事件的采样时间和事件的实际执行时长，这个结构体的代码如下所示：

```plain
struct latencySample {
    int32_t time;  //事件的采样时间
    uint32_t latency;  //事件的执行时长（以毫秒为单位）
};

```

而在latencySample这个结构体基础上，Redis又设计了**latencyTimeSeries结构体**，这个结构体使用了一个latencySample类型的数组，记录了针对某一类事件的一系列采样结果，这样就可以为分析Redis变慢提供更多的事件信息。

```plain
struct latencyTimeSeries {
    int idx;  //采样事件数组的写入位置
    uint32_t max;  //当前事件的最大延迟
    struct latencySample samples[LATENCY_TS_LEN]; //采样事件数组，记录LATENCY_TS_LEN个采样结果，LATENCY_TS_LEN默认为160
};

```

另外，也因为延迟监控框架要记录的延迟事件有很多种，所以Redis还进一步设计了一个**哈希表latency\_events**，作为全局变量server的一个成员变量，用来记录不同事件的采样结果数组，如下所示：

```plain
struct redisServer {
   …
   dict *latency_events;
   …
}

```

这个哈希表是在Redis server启动初始化的函数initServer中，通过调用latencyMonitorInit函数来完成创建的，如下所示：

```plain
void initServer(void) {
    …
    latencyMonitorInit();
}
 
void latencyMonitorInit(void) {
    server.latency_events = dictCreate(&latencyTimeSeriesDictType,NULL);
}

```

好，了解了记录延迟事件的数据结构和初始化操作后，我们再来看下事件采样是如何实现的。

### 如何实现延迟事件的采样？

延迟事件的**采样函数是latencyAddSample**，它的函数原型如下所示。它的参数中包含了要记录的事件名称，这实际是对应了latency\_events哈希表中的一个哈希项。此外，它的参数中还包括该事件的执行时长。

```plain
void latencyAddSample(char *event, mstime_t latency)

```

latencyAddSample函数的执行逻辑并不复杂，主要可以分成三步。

**首先**，它会根据传入的事件名称，在latency\_events哈希表中查找该事件。如果该事件对应的哈希项还不存在，它就会在哈希表中加入该事件，如下所示：

```plain
//查找事件对应的哈希项
struct latencyTimeSeries *ts = dictFetchValue(server.latency_events,event);
…
if (ts == NULL) { //如果哈希项为空，就新建哈希项
        ts = zmalloc(sizeof(*ts));
        ts->idx = 0;
        ts->max = 0;
        memset(ts->samples,0,sizeof(ts->samples));
        dictAdd(server.latency_events,zstrdup(event),ts); //在哈希表中插入哈希项
	}

```

**然后**，latencyAddSample函数会根据传入的事件执行时间，更新当前记录的该类事件的最大执行时间，如下所示：

```plain
if (latency > ts->max) ts->max = latency;

```

**最后**，latencyAddSample函数会实际记录当前的采样结果。

不过在这一步，如果它发现当前的采样结果，和前一个采样结果是在同一秒中获得的，并且如果当前采样结果的事件执行时长，大于前一个采样结果的话，那么latencyAddSample函数就会直接更新前一个采样结果中记录的执行时长了，而不是新插入一个采样结果。

否则的话，latencyAddSample函数才会新插入一个采样结果。这样设计的目的，也是为了避免在同一秒中记录过多的采样结果。

下面的代码展示了latencyAddSample函数实际记录采样结果的逻辑，你可以看下。

```plain
//获得同类事件的前一个采样结果
prev = (ts->idx + LATENCY_TS_LEN - 1) % LATENCY_TS_LEN;
if (ts->samples[prev].time == now) { //如果当前和前一个采样结果在同一秒中
        if (latency > ts->samples[prev].latency) //如果当前采用结果的执行时长大于前一个采样结果
            ts->samples[prev].latency = latency; //直接更新前一个采样结果的执行时长
        return;
    }
//否则，新插入当前的采样结果
ts->samples[ts->idx].time = time(NULL);
ts->samples[ts->idx].latency = latency;

```

而在这里，你也要注意一点，就是latencyAddSample函数在记录采样结果时，**会重复使用采样结果数组latencyTimeSeries**。所以，如果采样结果数量超过数组默认大小时，旧的采样结果是会被覆盖掉的。如果你要记录更多的采样结果，就需要扩大latencyTimeSeries数组的长度。

那么，latencyAddSample函数是在什么时候调用进行采样的呢?

其实，latencyAddSample函数是被封装在了**latencyAddSampleIfNeeded函数**中。在latencyAddSampleIfNeeded函数中，它只会在事件执行时长超过latency-monitor-threshold配置项的值时，才调用latencyAddSample函数记录采样结果。你可以看看下面给出的latencyAddSampleIfNeeded函数定义。

```plain
#define latencyAddSampleIfNeeded(event,var) \
    if (server.latency_monitor_threshold && \
        (var) >= server.latency_monitor_threshold) \
          latencyAddSample((event),(var));

```

而latencyAddSampleIfNeeded函数，实际上会在刚才介绍的延迟事件发生时被调用。这里我来给你举两个例子。

比如，当Redis命令通过call函数（在server.c文件中）执行时，call函数就会调用latencyAddSampleIfNeeded函数进行采样，如下所示：

```plain
if (flags & CMD_CALL_SLOWLOG && c->cmd->proc != execCommand) {
        //根据命令数据结构中flags的CMD_FAST标记，决定当前是fast-command事件还是command事件
        char *latency_event = (c->cmd->flags & CMD_FAST) ?
                              "fast-command" : "command";
        latencyAddSampleIfNeeded(latency_event,duration/1000);
        …
}

```

再比如，当Redis调用flushAppendOnlyFile函数写AOF文件时，如果AOF文件刷盘的配置项是AOF\_FSYNC\_ALWAYS，那么flushAppendOnlyFile函数就会调用latencyAddSampleIfNeeded函数，记录aof-fsync-always延迟事件的采样结果，如下所示：

```plain
void flushAppendOnlyFile(int force) {
…
if (server.aof_fsync == AOF_FSYNC_ALWAYS) {
latencyStartMonitor(latency); //调用latencyStartMonitor函数开始计时
redis_fsync(server.aof_fd); //实际将数据写入磁盘
        latencyEndMonitor(latency); //调用latencyEndMonitor结束计时，并计算时长
        latencyAddSampleIfNeeded("aof-fsync-always",latency);
…}
}

```

那么在这里，你需要注意的是，Redis源码在调用latencyAddSampleIfNeeded函数记录采样结果时，经常会在延迟事件执行前，调用**latencyStartMonitor函数**开始计时，并在事件执行结束后，调用**latencyEndMonitor函数**结束计时和计算事件执行时长。

此外，你也可以在阅读Redis源码的工具中，比如sublime、sourceinsight等，通过查找函数关系调用，找到latencyAddSampleIfNeeded函数被调用的其他地方。

好了，到这里，Redis延迟监控框架就能通过latencyAddSampleIfNeeded函数，来记录延迟事件的采样结果了。而实际上，Redis延迟监控框架还实现了延迟分析，并能提供应对延迟变慢的建议，我们再来看下。

### 延迟分析和提供应对措施建议

首先，Redis是提供了latency doctor命令，来给出延迟分析结果和应对方法建议的。当我们执行这条命令的时候，Redis就会使用latencyCommand函数来处理。而在处理这个命令时，latencyCommand函数会调用**createLatencyReport函数**，来生成延迟分析报告和应对方法建议。

具体来说，createLatencyReport函数会针对latency\_events哈希表中记录的每一类事件，先调用analyzeLatencyForEvent函数，计算获得采样的延迟事件执行时长的均值、最大/最小值等统计结果。具体的统计计算过程，你可以仔细阅读下analyzeLatencyForEvent函数的源码。

然后，createLatencyReport函数会针对这类事件，结合Redis配置项等信息给出应对措施。

其实，在createLatencyReport函数中，**它定义了多个int变量，当这些变量的值为1时，就表示建议Redis使用者采用一种应对高延迟的措施**。我在下面的代码中展示了部分应对措施对应的变量，你可以看下。另外你也可以阅读createLatencyReport函数源码，去了解所有的措施。

```plain
sds createLatencyReport(void) {
…
int advise_slowlog_enabled = 0;  //建议启用slowlog
int advise_slowlog_tuning = 0;   //建议重新配置slowlog阈值
int advise_slowlog_inspect = 0;   //建议检查slowlog结果
int advise_disk_contention = 0;   //建议减少磁盘竞争
…
}

```

我们也来简单举个例子。比如说，针对command事件，createLatencyReport函数就会根据slowlog的设置情况，给出启用slowlog、调整slowlog阈值、检查slowlog日志结果和避免使用bigkey的应对建议。这部分代码如下所示：

```plain
if (!strcasecmp(event,"command")) {
   //如果没有启用slowlog，则建议启用slowlog
   if (server.slowlog_log_slower_than < 0) {
       advise_slowlog_enabled = 1;
       advices++;
	}  //如果slowlog使用的命令时长阈值太大，建议调整slowlog阈值
	else if (server.slowlog_log_slower_than/1000 >
            server.latency_monitor_threshold)
            {
                advise_slowlog_tuning = 1;
                advices++;
            }
            advise_slowlog_inspect = 1; //建议检查slowlog结果
            advise_large_objects = 1; //建议避免使用bigkey
            advices += 2;
        }

```

所以，像createLatencyReport函数这样在计算延迟统计结果的同时，也给出应对措施的设计就很不错，这也是从Redis开发者的角度给出的建议，它更具有针对性。

好了，到这里，我们就了解了延迟监控框架的实现。接下来，我们再来学习下Redis中慢命令日志的实现。

## 慢命令日志的实现

Redis是使用了一个较为简单的方法来记录慢命令日志，也就是用一个列表，把执行时间超出慢命令日志执行时间阈值的命令记录下来。

在Redis全局变量server对应的数据结构redisServer中，有一个list类型的成员变量**slowlog**，它就是用来记录慢命令日志的列表的，如下所示：

```plain
struct redisServer {
…
list *slowlog;
…}

```

而实现慢命令日志记录功能的代码是在[slowlog.c](https://github.com/redis/redis/tree/5.0/src/slowlog.c)文件中。这里的主要函数是**slowlogPushEntryIfNeeded**，它的原型如下所示：

```plain
void slowlogPushEntryIfNeeded(client *c, robj **argv, int argc, long long duration)

```

从代码中你可以看到，这个函数的参数包含了当前执行命令及其参数argv，以及当前命令的执行时长duration。

这个函数的逻辑也不复杂，它会判断当前命令的执行时长duration，是否大于redis.conf配置文件中的慢命令日志阈值slowlog-log-slower-than。如果大于的话，它就会调用slowlogCreateEntry函数，为这条命令创建一条慢命令日志项，并调用listAddNodeHeader函数，把这条日志项加入到日志列表头，如下所示：

```plain
//当前命令的执行时长是否大于配置项
if (duration >= server.slowlog_log_slower_than)
   listAddNodeHead(server.slowlog, slowlogCreateEntry(c,argv,argc,duration));

```

当然，如果日志列表中记录了太多日志项，它消耗的内存资源也会增加。所以slowlogPushEntryIfNeeded函数在添加日志项时，会判断整个日志列表的长度是否超过配置项slowlog-max-len。一旦超过了，它就会把列表末尾的日志项删除，如下所示：

```plain
//如果日志列表超过阈值长度，就删除列表末尾的日志项
while (listLength(server.slowlog) > server.slowlog_max_len)
        listDelNode(server.slowlog,listLast(server.slowlog));

```

现在，我们也就了解了记录慢命令日志项的主要函数，slowlogPushEntryIfNeeded的基本逻辑了。然后我们再来看下，它在记录日志项时调用的**slowlogCreateEntry函数**。

这个函数是用来创建一个慢命令日志项。慢命令日志项的数据结构是slowlogEntry，如下所示：

```plain
typedef struct slowlogEntry {
    robj **argv;     //日志项对应的命令及参数
    int argc;        //日志项对应的命令及参数个数
    long long id;       //日志项的唯一ID
    long long duration;  //日志项对应命令的执行时长（以微秒为单位）
    time_t time;        //日志项对应命令的执行时间戳
    sds cname;          //日志项对应命令的发送客户端名称
    sds peerid;         //日志项对应命令的发送客户端网络地址
} slowlogEntry;

```

从slowLogEntry的定义中，你可以看到，它会把慢命令及其参数，以及发送命令的客户端网络地址记录下来。**这样设计的好处是**，当我们分析慢命令日志时，就可以直接看到慢命令本身及其参数了，而且可以知道发送命令的客户端信息。而这些信息，就有利于我们排查慢命令的起因和来源。

比如说，如果我们发现日志中记录的命令参数非常多，那么它就可能是一条操作bigkey的命令。

当然，考虑到内存资源有限，slowlogCreateEntry函数在创建慢命令日志项时，也会判断命令参数个数。如果命令参数个数，超出了阈值SLOWLOG\_ENTRY\_MAX\_ARGC这个宏定义的大小（默认32）时，它就不会记录超出阈值的参数了，而是记录下剩余的参数个数。这样一来，慢命令日志项中就既记录了部分命令参数，有助于排查问题，也避免了记录过多参数，占用过多内存。

下面的代码展示了slowlogCreateEntry的基本执行逻辑，你可以看下。

```plain
slowlogEntry *slowlogCreateEntry(client *c, 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;
…
for (j = 0; j < slargc; j++) {  //逐一记录命令及参数
   if (slargc != argc && j == slargc-1) {  //如果命令参数个数超出阈值，使用最后一个参数记录当前命令实际剩余的参数个数
      se->argv[j] = createObject(OBJ_STRING,
                sdscatprintf(sdsempty(),"... (%d more arguments)",
                argc-slargc+1));
        } else {
        …  //将命令参数填充到日志项中
        }}
… //将命令执行时长、客户端地址等信息填充到日志项中
}

```

好了，到这里，你就了解了慢命令日志的实现。最后，你也要注意，**慢命令日志只会记录超出执行时长阈值的命令信息**，而不会像延迟监控框架那样记录多种事件。所以，记录日志的函数slowlogPushEntryIfNeeded，只会在命令执行函数call（在server.c文件中）中被调用，如下所示：

```plain
void call(client *c, int flags) {
…
start = server.ustime; //命令执行前计时
c->cmd->proc(c);  //命令实际执行
duration = ustime()-start; //命令执行完成计算耗时
…
if (flags & CMD_CALL_SLOWLOG && c->cmd->proc != execCommand) {
        …
        //调用slowlogPushEntryIfNeeded函数记录慢命令
        slowlogPushEntryIfNeeded(c,c->argv,c->argc,duration);
	}
…}

```

## 小结

今天这节课，我给你介绍了Redis实现的延迟监控框架和慢命令日志。你要知道，Redis源码会针对可能导致Redis运行变慢的五类事件，在它们执行时进行**采样**。而一旦这些事件的执行时长超过阈值时，监控框架就会将采样结果记录下来，以便后续分析使用。这种针对延迟事件进行采样记录的监控方法，其实是很值得我们学习的。

而慢命令日志的实现则较为简单，就是针对运行时长超出阈值的命令，使用一个**列表**把它们记录下来，这里面包括了命令及参数，以及发送命令的客户端信息，这样可以方便运维人员查看分析。

当然，Redis源码中实现的延迟监控框架主要是关注导致延迟增加的事件，它记录的延迟事件，也是和Redis运行过程中可能会导致运行变慢的操作**紧耦合**的。此外，Redis的INFO命令也提供了Redis运行时的监控信息，不过你要知道，INFO命令的实现，主要是在全局变量server的成员变量中，用来记录Redis实例的实时运行状态或是资源使用情况的。

## 每课一问

Redis在命令执行的call函数中，为什么不会针对EXEC命令，调用slowlogPushEntryIfNeeded函数记录慢命令呢？