From 6749efc06babe4b30df18b36a0ee9037b2eacf05 Mon Sep 17 00:00:00 2001 From: doyoubi Date: Mon, 6 Feb 2017 12:10:29 +0000 Subject: [PATCH] Add slowlog entry for slowest sub command --- README.md | 10 +++++++--- src/command.c | 15 ++++++++++++++- src/command.h | 10 +++++++++- src/slowlog.c | 28 ++++++++++++++++++++++++++++ src/slowlog.h | 2 ++ 5 files changed, 60 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index a366de1..701388f 100644 --- a/README.md +++ b/README.md @@ -96,9 +96,13 @@ Commands * `DEL`: split to multiple single key `DEL`. * `EXISTS`: split to multiple single key `EXISTS`. * `PING`: ignored and won't be forwarded. -* `INFO`, `TIME`, `SLOWLOG`: won't be forwarded to backend redis, information collected in proxy - will be returned. Note that in the slowlog entry there's an additional - `remote latency` field before the `total latency` field. +* `INFO`, `TIME`: won't be forwarded to backend redis, information collected in proxy + will be returned. +* `SLOWLOG`: return the slowlogs saved by corvus itself. Note that unlike redis, + in the slowlog entry there's an additional `remote latency` field before + the `total latency` field. The slowlog will also log the slowest + sub command for multiple-key commands: `MGET`, `MSET`, `DEL`, `EXISTS`. + The total latency of sub cmd entry will just be the same as its parent cmd. * `AUTH`: do authentication in proxy. #### Restricted commands diff --git a/src/command.c b/src/command.c index 3d859f8..4cfd312 100644 --- a/src/command.c +++ b/src/command.c @@ -280,6 +280,9 @@ int cmd_forward_multikey(struct command *cmd, struct redis_data *data, const cha memcpy(&ncmd->req_buf[0], &key->buf[0], sizeof(key->buf[0])); memcpy(&ncmd->req_buf[1], &key->buf[1], sizeof(key->buf[1])); ncmd->prefix = (char*)prefix; + ncmd->data.type = REP_ARRAY; + ncmd->data.elements = 1; + ncmd->data.element = key; if (cmd_forward_basic(ncmd) == CORVUS_ERR) { cmd_mark_fail(ncmd, rep_forward_err); @@ -321,6 +324,9 @@ int cmd_forward_mset(struct command *cmd, struct redis_data *data) memcpy(&ncmd->req_buf[0], &key->buf[0], sizeof(key->buf[0])); memcpy(&ncmd->req_buf[1], &value->buf[1], sizeof(value->buf[1])); ncmd->prefix = (char*)rep_set; + ncmd->data.type = REP_ARRAY; + ncmd->data.elements = 2; + ncmd->data.element = &data->element[i]; if (cmd_forward_basic(ncmd) == CORVUS_ERR) { cmd_mark_fail(ncmd, rep_forward_err); @@ -1138,6 +1144,10 @@ void cmd_stats(struct command *cmd, int64_t end_time) struct slowlog_entry *entry = slowlog_create_entry(cmd, remote_latency / 1000, total_latency / 1000); slowlog_set(&cmd->ctx->slowlog, entry); + entry = slowlog_create_sub_entry(cmd, total_latency / 1000); + if (entry) { + slowlog_set(&cmd->ctx->slowlog, entry); + } } } @@ -1224,7 +1234,10 @@ void cmd_free(struct command *cmd) struct command *c; struct context *ctx = cmd->ctx; - if (cmd->data.type != REP_UNKNOWN) { + // When cmd->prefix is not NULL it's a sub command, + // cmd->data of sub command is a weak reference + // and should never be deallocated. + if (cmd->data.type != REP_UNKNOWN && cmd->prefix == NULL) { redis_data_free(&cmd->data); cmd->data.type = REP_UNKNOWN; } diff --git a/src/command.h b/src/command.h index f30d2eb..6e066de 100644 --- a/src/command.h +++ b/src/command.h @@ -232,7 +232,15 @@ struct command { bool stale; bool cmd_fail; - struct redis_data data; /* for slowlog */ + /* For slowlog + When used in parent cmd or non-multiple-key command, + it contains all command data. When used in sub command, + it does not contain command name because it's already + in command.prefix. Note that in sub command it's only a + weak reference to command.data of parent cmd and should never + be deallocated. + */ + struct redis_data data; }; struct redirect_info { diff --git a/src/slowlog.c b/src/slowlog.c index da9d528..dafed38 100644 --- a/src/slowlog.c +++ b/src/slowlog.c @@ -111,6 +111,33 @@ struct slowlog_entry *slowlog_create_entry(struct command *cmd, int64_t remote_l return entry; } +// Return NULL when `cmd` is not a multiple keys command +struct slowlog_entry *slowlog_create_sub_entry(struct command *cmd, int64_t total_latency) +{ + switch (cmd->cmd_type) { + case CMD_MGET: + case CMD_MSET: + case CMD_DEL: + case CMD_EXISTS: + break; + default: + return NULL; + } + if (STAILQ_EMPTY(&cmd->sub_cmds)) { + return NULL; + } + int64_t max_remote_latency = 0; + struct command *c, *slowest_sub_cmd = NULL; + STAILQ_FOREACH(c, &cmd->sub_cmds, sub_cmd_next) { + int64_t remote_latency = c->rep_time[1] - c->rep_time[0]; + if (remote_latency > max_remote_latency) { + max_remote_latency = remote_latency; + slowest_sub_cmd = c; + } + } + return slowlog_create_entry(slowest_sub_cmd, max_remote_latency / 1000, total_latency); +} + void slowlog_dec_ref(struct slowlog_entry *entry) { int refcount = ATOMIC_DEC(entry->refcount, 1); @@ -173,6 +200,7 @@ bool slowlog_need_log(struct command *cmd, long long latency) { return config.slowlog_log_slower_than >= 0 && slowlog_type_need_log(cmd) + && cmd->data.elements > 0 // for mget, mset, exists, del && latency > config.slowlog_log_slower_than * 1000; } diff --git a/src/slowlog.h b/src/slowlog.h index 022c787..bb1a57c 100644 --- a/src/slowlog.h +++ b/src/slowlog.h @@ -39,6 +39,8 @@ void slowlog_free(struct slowlog_queue *slowlog); // only called by the thread who creates the log struct slowlog_entry *slowlog_create_entry(struct command *cmd, int64_t remote_latency, int64_t total_latency); +// create entry for the slowlest sub cmd, its total_latency should be the same as parent cmd +struct slowlog_entry *slowlog_create_sub_entry(struct command *cmd, int64_t total_latency); // called by all worker threads void slowlog_set(struct slowlog_queue *queue, struct slowlog_entry *entry); void slowlog_dec_ref(struct slowlog_entry *entry);