diff --git a/src/command.c b/src/command.c index 0f25305..3d859f8 100644 --- a/src/command.c +++ b/src/command.c @@ -597,12 +597,13 @@ int cmd_slowlog_get(struct command *cmd, struct redis_data *data) // generate redis packet const char *hdr_fmt = - "*4\r\n" + "*5\r\n" ":%lld\r\n" // id ":%lld\r\n" // log time - ":%lld\r\n" // latency + ":%lld\r\n" // remote latency + ":%lld\r\n" // total latency "*%d\r\n"; // cmd arg len - char buf[150]; + char buf[200]; int size = snprintf(buf, sizeof buf, "*%d\r\n", count); conn_add_data(cmd->client, (uint8_t*)buf, size, @@ -612,7 +613,7 @@ int cmd_slowlog_get(struct command *cmd, struct redis_data *data) struct slowlog_entry *entry = entries[i]; assert(entry->argc > 0); size = snprintf(buf, sizeof buf, hdr_fmt, - entry->id, entry->log_time, entry->latency, entry->argc); + entry->id, entry->log_time, entry->remote_latency, entry->total_latency, entry->argc); assert(size < 150); conn_add_data(cmd->client, (uint8_t*)buf, size, NULL, NULL); @@ -1118,28 +1119,29 @@ void cmd_mark_fail(struct command *cmd, const char *reason) void cmd_stats(struct command *cmd, int64_t end_time) { struct context *ctx = cmd->ctx; - long long latency; + long long remote_latency, total_latency; ATOMIC_INC(ctx->stats.completed_commands, 1); - latency = end_time - cmd->parse_time; + total_latency = end_time - cmd->parse_time; - ATOMIC_INC(ctx->stats.total_latency, latency); - ATOMIC_SET(ctx->last_command_latency, latency); + ATOMIC_INC(ctx->stats.total_latency, total_latency); + ATOMIC_SET(ctx->last_command_latency, total_latency); - latency = cmd->rep_time[1] - cmd->rep_time[0]; + remote_latency = cmd->rep_time[1] - cmd->rep_time[0]; - if (slowlog_need_log(cmd, latency)) { + if (slowlog_need_log(cmd, total_latency)) { if (slowlog_statsd_enabled()) { slowlog_add_count(cmd); } if (slowlog_cmd_enabled()) { - struct slowlog_entry *entry = slowlog_create_entry(cmd, latency / 1000); + struct slowlog_entry *entry = slowlog_create_entry(cmd, + remote_latency / 1000, total_latency / 1000); slowlog_set(&cmd->ctx->slowlog, entry); } } - ATOMIC_INC(ctx->stats.remote_latency, latency); + ATOMIC_INC(ctx->stats.remote_latency, remote_latency); } void cmd_set_stale(struct command *cmd) diff --git a/src/slowlog.c b/src/slowlog.c index d7366ee..da9d528 100644 --- a/src/slowlog.c +++ b/src/slowlog.c @@ -50,12 +50,13 @@ void slowlog_free(struct slowlog_queue *slowlog) cv_free(slowlog->entry_locks); } -struct slowlog_entry *slowlog_create_entry(struct command *cmd, int64_t latency) +struct slowlog_entry *slowlog_create_entry(struct command *cmd, int64_t remote_latency, int64_t total_latency) { struct slowlog_entry *entry = cv_calloc(1, sizeof(struct slowlog_entry)); entry->id = ATOMIC_INC(slowlog_id, 1); entry->log_time = time(NULL); // redis also uses time(NULL); - entry->latency = latency; + entry->remote_latency = remote_latency; + entry->total_latency = total_latency; entry->refcount = 1; const char *bytes_fmt = "(%zd bytes)"; diff --git a/src/slowlog.h b/src/slowlog.h index bf5652c..022c787 100644 --- a/src/slowlog.h +++ b/src/slowlog.h @@ -17,7 +17,8 @@ struct slowlog_entry { long long id; long long log_time; - long long latency; + long long remote_latency; + long long total_latency; int refcount; int argc; struct pos argv[SLOWLOG_ENTRY_MAX_ARGC]; @@ -37,7 +38,7 @@ int slowlog_init(struct slowlog_queue *slowlog); 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 latency); +struct slowlog_entry *slowlog_create_entry(struct command *cmd, int64_t remote_latency, 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); diff --git a/tests/test_slowlog.c b/tests/test_slowlog.c index e3de396..3e89df4 100644 --- a/tests/test_slowlog.c +++ b/tests/test_slowlog.c @@ -23,8 +23,9 @@ TEST(test_slowlog_create_entry) { cmd.data = r.data; cmd.prefix = NULL; - struct slowlog_entry *entry = slowlog_create_entry(&cmd, 233666); - ASSERT(entry->latency == 233666); + struct slowlog_entry *entry = slowlog_create_entry(&cmd, 233666, 666233); + ASSERT(entry->remote_latency == 233666); + ASSERT(entry->total_latency == 666233); ASSERT(entry->refcount == 1); ASSERT(entry->argc == 3); ASSERT(entry->argv[0].len == args_len[0]); @@ -80,8 +81,9 @@ TEST(test_slowlog_create_entry_with_prefix) { cmd.data.type = REP_ARRAY; cmd.prefix = (char*)rep_set; - struct slowlog_entry *entry = slowlog_create_entry(&cmd, 9394); - ASSERT(entry->latency == 9394); + struct slowlog_entry *entry = slowlog_create_entry(&cmd, 9394, 9493); + ASSERT(entry->remote_latency == 9394); + ASSERT(entry->total_latency == 9493); ASSERT(entry->refcount == 1); ASSERT(entry->argc == 3); ASSERT(entry->argv[0].len == args_len[0]); @@ -130,7 +132,7 @@ TEST(test_slowlog_create_entry_with_long_arg) { cmd.data = r.data; cmd.prefix = NULL; - struct slowlog_entry *entry = slowlog_create_entry(&cmd, 233666); + struct slowlog_entry *entry = slowlog_create_entry(&cmd, 233666, 666233); ASSERT(SLOWLOG_ENTRY_MAX_STRING == strlen(long_value)); ASSERT(entry->argv[1].len == strlen(long_value)); ASSERT(strncmp(long_value, entry->argv[1].str, strlen(long_value)) == 0);