慢日志相关代码
在Redis中，使用list来在内存中保存当前实例的慢日志，并使用slowlog_entry_id来记录下一条慢日志的编号，每次新插入慢日志时会slowlog_entry_id值进行加一操作。
struct redisServer {
list *slowlog; /* SLOWLOG list of commands */
long long slowlog_entry_id; /* SLOWLOG current entry ID */
long long slowlog_log_slower_than; /* SLOWLOG time limit (to get logged) */
unsigned long slowlog_max_len; /* SLOWLOG max number of items logged */
}
并通过参数slowlog-log-slower-than和slowlog-max-len来控制慢日志：
- slowlog-log-slower-than：指定超过多长时间的命令请求会被记录到慢日志中，单位是微秒。
- slowlog-max-len：指定在实例内存中最多保留的慢日志数量，单位是条。
使用slowlogEntry来存放单条慢日志信息，其中包含：客户端信息、请求命令信息、慢日志编号、请求执行时间、请求执行耗时等信息。
/* This structure defines an entry inside the slow log list */
typedef struct slowlogEntry {
robj **argv;
int argc;
long long id; /* Unique entry identifier. */
long long duration; /* Time spent by the query, in microseconds. */
time_t time; /* Unix time at which the query was executed. */
sds cname; /* Client name. */
sds peerid; /* Client network address. */
} slowlogEntry;
在每条命令请求执行时(call函数调用)，会计算该命令的执行耗时，并作为是否记录到慢日志的判定标准。
该执行耗时不包含：
- 客户端将命令发送到Redis服务器的网络耗时。
- 命令在文件事件处理队列中等待被工作线程处理的耗时。
- 工作线程执行命令后将执行结果转交给网络接口等待网络传输的耗时。
- Redis服务器将执行结果发送给客户端的网络耗时。
- Redis命令异步处理的执行耗时，如unlink命令执行后异步删除的时间。
/* Call() is the core of Redis execution of a command.
*/
void call(client *c, int flags) {
......
/* Call the command. */
start = server.ustime;
c->cmd->proc(c);
duration = ustime()-start;
/* Log the command into the Slow log if needed, and populate the
* per-command statistics that we show in INFO commandstats. */
if (flags & CMD_CALL_SLOWLOG && c->cmd->proc != execCommand) {
char *latency_event = (c->cmd->flags & CMD_FAST) ?
"fast-command" : "command";
latencyAddSampleIfNeeded(latency_event,duration/1000);
slowlogPushEntryIfNeeded(c,c->argv,c->argc,duration);
......
}
在尝试插入慢日志的函数(slowlogPushEntryIfNeeded)中，执行下面操作：
- 判断该命令执行时间是否满足慢日志请求的阈值(slowlog-log-slower-than)，满足则放入慢日志请求列表。
- 检查慢日志列表长度是否超过阈值(slowlog-max-len)，超过则对慢日志列表进行裁剪。
/* 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(client *c, robj **argv, int argc, long long duration) {
if (server.slowlog_log_slower_than < 0) return; /* Slowlog disabled */
if (duration >= server.slowlog_log_slower_than)
listAddNodeHead(server.slowlog,
slowlogCreateEntry(c,argv,argc,duration));
/* Remove old entries if needed. */
while (listLength(server.slowlog) > server.slowlog_max_len)
listDelNode(server.slowlog,listLast(server.slowlog));
}
在生成慢日志对象(slowlogCreateEntry)时，会对请求命令的信息进行裁剪，避免单条慢日志信息过大，同时会对server.slowlog_entry_id进行递增。
/* Create a new slowlog entry.
* Incrementing the ref count of all the objects retained is up to
* this function. */
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;
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(OBJ_STRING,
sdscatprintf(sdsempty(),"... (%d more arguments)",
argc-slargc+1));
} else {
/* Trim too long strings as well... */
if (argv[j]->type == OBJ_STRING &&
sdsEncodedObject(argv[j]) &&
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(OBJ_STRING,s);
} else if (argv[j]->refcount == OBJ_SHARED_REFCOUNT) {
se->argv[j] = argv[j];
} else {
/* Here we need to dupliacate the string objects composing the
* argument vector of the command, because those may otherwise
* end shared with string objects stored into keys. Having
* shared objects between any part of Redis, and the data
* structure holding the data, is a problem: FLUSHALL ASYNC
* may release the shared string object and create a race. */
se->argv[j] = dupStringObject(argv[j]);
}
}
}
se->time = time(NULL);
se->duration = duration;
se->id = server.slowlog_entry_id++;
se->peerid = sdsnew(getClientPeerId(c));
se->cname = c->name ? sdsnew(c->name->ptr) : sdsempty();
return se;
}
学习总结
由于Redis中根据命令请求在工作线程中真实执行时间来判断是否记录到慢日志列表中，因此不能简单依据慢日志信息来判断是否存在客户端请求执行慢的情况。
当出现客户端请求Redis较慢时，需排查出现问题时间点：
- 客户端服务器各项指标是否正常(CPU/内存/存储/网络)。
- 客户端到Redis服务器的网络是否正常，是否网络带宽异常或网络丢包重传等情况。
- Redis服务器CPU是否正常，是否存在其他服务和Redis服务器争抢CPU资源。
- Redis服务器QPS是否正常，是否存在QPS请求暴涨情况，导致请求在Redis服务器端阻塞。
- Redis服务器内存是否正常，是否存在Redis实例内存达到上限触发主动内存淘汰策略。
- Redis服务器是否开启[内存大页]设置，导致单次请求内存过大消耗较长时间。
- Redis服务器SWAP是否正常，是否存在Redis大量数据SWAP到存储空间的问题。
- Redis服务器IO是否正常，是否存在IO瓶颈，是否由AOF重写或RDB备份或其他服务操作导致IO争抢。
- Redis实例是否占用内存过大，存在RDB备份和AOF重写时FORK操作耗时较长问题。
- Redis实例是否存在超大KEY，接收和发送或异步删除以及COW拷贝超大KEY时操作耗时较长。
- Redis实例是否是否存在严重耗时操作，如KEYS、SCAN、HSCAN、MGET、HGETALL等操作。
- Redis实例是否存在批量过期性能，在同一时间点过期大量数据，导致默认每100ms执行的定时任务中长时间执行[主动过期清理]的操作(将过期数据占比下降到25%或清理时长超过25ms)。
- Redis实例是否设置内存碎片自动清理策略，内存清理过程中会消耗CPU资源。
- Redis是否绑定特定CPU,存在特定CPU上的资源争抢或未绑定CPU导致频繁上线文切换。
- Redis从库是否存在异常，导致重新全量同步数据或拉取大量增量日志，导致网络带宽问题。