Add total latency to slowlog

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)

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)";

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);

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);