Slowlog backported to 2.2

deps/hiredis/hiredis.c

@@ -50,7 +50,7 @@ typedef struct redisReader {
     size_t pos; /* buffer cursor */
     size_t len; /* buffer length */
 
-    redisReadTask rstack[3]; /* stack of read tasks */
+    redisReadTask rstack[9]; /* stack of read tasks */
     int ridx; /* index of stack */
     void *privdata; /* user-settable arbitrary field */
 } redisReader;
@@ -340,9 +340,9 @@ static int processMultiBulkItem(redisReader *r) {
     int root = 0;
 
     /* Set error for nested multi bulks with depth > 1 */
-    if (r->ridx == 2) {
+    if (r->ridx == 8) {
         redisSetReplyReaderError(r,sdscatprintf(sdsempty(),
-            "No support for nested multi bulk replies with depth > 1"));
+            "No support for nested multi bulk replies with depth > 7"));
         return -1;
     }
 

redis.conf

@@ -292,6 +292,30 @@ appendfsync everysec
 # "no" that is the safest pick from the point of view of durability.
 no-appendfsync-on-rewrite no
 
+################################## SLOW LOG ###################################
+
+# The Redis Slow Log is a system to log queries that exceeded a specified
+# execution time. The execution time does not include the I/O operations
+# like talking with the client, sending the reply and so forth,
+# but just the time needed to actually execute the command (this is the only
+# stage of command execution where the thread is blocked and can not serve
+# other requests in the meantime).
+# 
+# You can configure the slow log with two parameters: one tells Redis
+# what is the execution time, in microseconds, to exceed in order for the
+# command to get logged, and the other parameter is the length of the
+# slow log. When a new command is logged the oldest one is removed from the
+# queue of logged commands.
+
+# The following time is expressed in microseconds, so 1000000 is equivalent
+# to one second. Note that a negative number disables the slow log, while
+# a value of zero forces the logging of every command.
+slowlog-log-slower-than 10000
+
+# There is no limit to this length. Just be aware that it will consume memory.
+# You can reclaim memory used by the slow log with SLOWLOG RESET.
+slowlog-log-len 1024
+
 ################################ VIRTUAL MEMORY ###############################
 
 # Virtual Memory allows Redis to work with datasets bigger than the actual

src/Makefile

@@ -25,7 +25,7 @@ PREFIX= /usr/local
 INSTALL_BIN= $(PREFIX)/bin
 INSTALL= cp -p
 
-OBJ = adlist.o ae.o anet.o dict.o redis.o sds.o zmalloc.o lzf_c.o lzf_d.o pqsort.o zipmap.o sha1.o ziplist.o release.o networking.o util.o object.o db.o replication.o rdb.o t_string.o t_list.o t_set.o t_zset.o t_hash.o config.o aof.o vm.o pubsub.o multi.o debug.o sort.o intset.o syncio.o
+OBJ = adlist.o ae.o anet.o dict.o redis.o sds.o zmalloc.o lzf_c.o lzf_d.o pqsort.o zipmap.o sha1.o ziplist.o release.o networking.o util.o object.o db.o replication.o rdb.o t_string.o t_list.o t_set.o t_zset.o t_hash.o config.o aof.o vm.o pubsub.o multi.o debug.o sort.o intset.o syncio.o slowlog.o
 BENCHOBJ = ae.o anet.o redis-benchmark.o sds.o adlist.o zmalloc.o
 CLIOBJ = anet.o sds.o adlist.o redis-cli.o zmalloc.o release.o
 CHECKDUMPOBJ = redis-check-dump.o lzf_c.o lzf_d.o
@@ -51,7 +51,6 @@ ae_select.o: ae_select.c
 anet.o: anet.c fmacros.h anet.h
 aof.o: aof.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
-chprgname.o: chprgname.c
 config.o: config.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 db.o: db.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
@@ -73,21 +72,26 @@ pubsub.o: pubsub.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 rdb.o: rdb.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h lzf.h
-redis-benchmark.o: redis-benchmark.c fmacros.h ae.h anet.h sds.h adlist.h \
-  zmalloc.h
+redis-benchmark.o: redis-benchmark.c fmacros.h ae.h \
+  ../deps/hiredis/hiredis.h sds.h adlist.h zmalloc.h
 redis-check-aof.o: redis-check-aof.c fmacros.h config.h
 redis-check-dump.o: redis-check-dump.c lzf.h
-redis-cli.o: redis-cli.c fmacros.h version.h sds.h adlist.h zmalloc.h
+redis-cli.o: redis-cli.c fmacros.h version.h ../deps/hiredis/hiredis.h \
+  sds.h zmalloc.h ../deps/linenoise/linenoise.h help.h
 redis.o: redis.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
-  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h slowlog.h
 release.o: release.c release.h
 replication.o: replication.c redis.h fmacros.h config.h ae.h sds.h dict.h \
   adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 sds.o: sds.c sds.h zmalloc.h
 sha1.o: sha1.c sha1.h
+slowlog.o: slowlog.c redis.h fmacros.h config.h ae.h sds.h dict.h \
+  adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h \
+  slowlog.h
 sort.o: sort.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h pqsort.h
-syncio.o: syncio.c
+syncio.o: syncio.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 t_hash.o: t_hash.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 t_list.o: t_list.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
@@ -104,7 +108,7 @@ vm.o: vm.c redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
   zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h
 ziplist.o: ziplist.c zmalloc.h ziplist.h
 zipmap.o: zipmap.c zmalloc.h
-zmalloc.o: zmalloc.c config.h
+zmalloc.o: zmalloc.c config.h zmalloc.h
 
 dependencies:
 	cd ../deps/hiredis && $(MAKE) static ARCH="$(ARCH)"
@@ -139,7 +143,7 @@ clean:
 	rm -rf $(PRGNAME) $(BENCHPRGNAME) $(CLIPRGNAME) $(CHECKDUMPPRGNAME) $(CHECKAOFPRGNAME) *.o *.gcda *.gcno *.gcov
 
 dep:
-	$(CC) -MM *.c
+	$(CC) -MM *.c -I ../deps/hiredis -I ../deps/linenoise
 
 test: redis-server
 	(cd ..; tclsh8.5 tests/test_helper.tcl --tags "${TAGS}" --file "${FILE}")

src/config.c

@@ -288,6 +288,12 @@ void loadServerConfig(char *filename) {
                     err = "Target command name already exists"; goto loaderr;
                 }
             }
+        } else if (!strcasecmp(argv[0],"slowlog-log-slower-than") &&
+                   argc == 2)
+        {
+            server.slowlog_log_slower_than = strtoll(argv[1],NULL,10);
+        } else if (!strcasecmp(argv[0],"slowlog-max-len") && argc == 2) {
+            server.slowlog_max_len = strtoll(argv[1],NULL,10);
         } else {
             err = "Bad directive or wrong number of arguments"; goto loaderr;
         }
@@ -446,6 +452,12 @@ void configSetCommand(redisClient *c) {
     } else if (!strcasecmp(c->argv[2]->ptr,"set-max-intset-entries")) {
         if (getLongLongFromObject(o,&ll) == REDIS_ERR || ll < 0) goto badfmt;
         server.set_max_intset_entries = ll;
+    } else if (!strcasecmp(c->argv[2]->ptr,"slowlog-log-slower-than")) {
+        if (getLongLongFromObject(o,&ll) == REDIS_ERR) goto badfmt;
+        server.slowlog_log_slower_than = ll;
+    } else if (!strcasecmp(c->argv[2]->ptr,"slowlog-max-len")) {
+        if (getLongLongFromObject(o,&ll) == REDIS_ERR || ll < 0) goto badfmt;
+        server.slowlog_max_len = (unsigned)ll;
     } else {
         addReplyErrorFormat(c,"Unsupported CONFIG parameter: %s",
             (char*)c->argv[2]->ptr);
@@ -597,6 +609,16 @@ void configGetCommand(redisClient *c) {
         addReplyBulkLongLong(c,server.set_max_intset_entries);
         matches++;
     }
+    if (stringmatch(pattern,"slowlog-log-slower-than",0)) {
+        addReplyBulkCString(c,"slowlog-log-slower-than");
+        addReplyBulkLongLong(c,server.slowlog_log_slower_than);
+        matches++;
+    }
+    if (stringmatch(pattern,"slowlog-max-len",0)) {
+        addReplyBulkCString(c,"slowlog-max-len");
+        addReplyBulkLongLong(c,server.slowlog_max_len);
+        matches++;
+    }
     setDeferredMultiBulkLength(c,replylen,matches*2);
 }
 

src/debug.c

@@ -289,6 +289,12 @@ void debugCommand(redisClient *c) {
             d = sdscatprintf(d, "%02x",digest[j]);
         addReplyStatus(c,d);
         sdsfree(d);
+    } else if (!strcasecmp(c->argv[1]->ptr,"sleep") && c->argc == 3) {
+        double dtime = strtod(c->argv[2]->ptr,NULL);
+        long long utime = dtime*1000000;
+
+        usleep(utime);
+        addReply(c,shared.ok);
     } else {
         addReplyError(c,
             "Syntax error, try DEBUG [SEGFAULT|OBJECT <key>|SWAPIN <key>|SWAPOUT <key>|RELOAD]");

src/redis.c

@@ -28,6 +28,7 @@
  */
 
 #include "redis.h"
+#include "slowlog.h"
 
 #ifdef HAVE_BACKTRACE
 #include <execinfo.h>
@@ -188,7 +189,8 @@ struct redisCommand readonlyCommandTable[] = {
     {"publish",publishCommand,3,REDIS_CMD_FORCE_REPLICATION,NULL,0,0,0},
     {"watch",watchCommand,-2,0,NULL,0,0,0},
     {"unwatch",unwatchCommand,1,0,NULL,0,0,0},
-    {"object",objectCommand,-2,0,NULL,0,0,0}
+    {"object",objectCommand,-2,0,NULL,0,0,0},
+    {"slowlog",slowlogCommand,-2,0,NULL,0,0,0}
 };
 
 /*============================ Utility functions ============================ */
@@ -831,6 +833,10 @@ void initServerConfig() {
     populateCommandTable();
     server.delCommand = lookupCommandByCString("del");
     server.multiCommand = lookupCommandByCString("multi");
+
+    /* Slow log */
+    server.slowlog_log_slower_than = REDIS_SLOWLOG_LOG_SLOWER_THAN;
+    server.slowlog_max_len = REDIS_SLOWLOG_MAX_LEN;
 }
 
 void initServer() {
@@ -917,6 +923,7 @@ void initServer() {
     }
 
     if (server.vm_enabled) vmInit();
+    slowlogInit();
     srand(time(NULL)^getpid());
 }
 
@@ -952,11 +959,13 @@ struct redisCommand *lookupCommandByCString(char *s) {
 
 /* Call() is the core of Redis execution of a command */
 void call(redisClient *c, struct redisCommand *cmd) {
-    long long dirty;
+    long long dirty, start = ustime(), duration;
 
     dirty = server.dirty;
     cmd->proc(c);
     dirty = server.dirty-dirty;
+    duration = ustime()-start;
+    slowlogPushEntryIfNeeded(c->argv,c->argc,duration);
 
     if (server.appendonly && dirty)
         feedAppendOnlyFile(cmd,c->db->id,c->argv,c->argc);

src/redis.h

@@ -49,6 +49,8 @@
 #define REDIS_SHARED_INTEGERS 10000
 #define REDIS_REPLY_CHUNK_BYTES (5*1500) /* 5 TCP packets with default MTU */
 #define REDIS_MAX_LOGMSG_LEN    1024 /* Default maximum length of syslog messages */
+#define REDIS_SLOWLOG_LOG_SLOWER_THAN 10000
+#define REDIS_SLOWLOG_MAX_LEN 64
 
 /* Hash table parameters */
 #define REDIS_HT_MINFILL        10      /* Minimal hash table fill 10% */
@@ -388,6 +390,10 @@ struct redisServer {
     long long stat_evictedkeys;     /* number of evicted keys (maxmemory) */
     long long stat_keyspace_hits;   /* number of successful lookups of keys */
     long long stat_keyspace_misses; /* number of failed lookups of keys */
+    list *slowlog;
+    long long slowlog_entry_id;
+    long long slowlog_log_slower_than;
+    unsigned long slowlog_max_len;
     /* Configuration */
     int verbosity;
     int maxidletime;

src/slowlog.c

@@ -0,0 +1,115 @@
+#include "redis.h"
+#include "slowlog.h"
+
+/* Slowlog implements a system that is able to remember the latest N
+ * queries that took more than M microseconds to execute.
+ *
+ * The execution time to reach to be logged in the slow log is set
+ * using the 'slowlog-log-slower-than' config directive, that is also
+ * readable and writable using the CONFIG SET/GET command.
+ *
+ * The slow queries log is actually not "logged" in the Redis log file
+ * but is accessible thanks to the SLOWLOG command. */
+
+/* Create a new slowlog entry.
+ * Incrementing the ref count of all the objects retained is up to
+ * this function. */
+slowlogEntry *slowlogCreateEntry(robj **argv, int argc, long long duration) {
+    slowlogEntry *se = zmalloc(sizeof(*se));
+    int j;
+
+    se->argc = argc;
+    se->argv = zmalloc(sizeof(robj*)*argc);
+    for (j = 0; j < argc; j++) {
+        se->argv[j] = argv[j];
+        incrRefCount(argv[j]);
+    }
+    se->time = time(NULL);
+    se->duration = duration;
+    se->id = server.slowlog_entry_id++;
+    return se;
+}
+
+/* Free a slow log entry. The argument is void so that the prototype of this
+ * function matches the one of the 'free' method of adlist.c.
+ *
+ * This function will take care to release all the retained object. */
+void slowlogFreeEntry(void *septr) {
+    slowlogEntry *se = septr;
+    int j;
+
+    for (j = 0; j < se->argc; j++)
+        decrRefCount(se->argv[j]);
+    zfree(se->argv);
+    zfree(se);
+}
+
+/* Initialize the slow log. This function should be called a single time
+ * at server startup. */
+void slowlogInit(void) {
+    server.slowlog = listCreate();
+    server.slowlog_entry_id = 0;
+    listSetFreeMethod(server.slowlog,slowlogFreeEntry);
+}
+
+/* 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(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(argv,argc,duration));
+
+    /* Remove old entries if needed. */
+    while (listLength(server.slowlog) > server.slowlog_max_len)
+        listDelNode(server.slowlog,listLast(server.slowlog));
+}
+
+/* Remove all the entries from the current slow log. */
+void slowlogReset(void) {
+    while (listLength(server.slowlog) > 0)
+        listDelNode(server.slowlog,listLast(server.slowlog));
+}
+
+/* The SLOWLOG command. Implements all the subcommands needed to handle the
+ * Redis slow log. */
+void slowlogCommand(redisClient *c) {
+    if (c->argc == 2 && !strcasecmp(c->argv[1]->ptr,"reset")) {
+        slowlogReset();
+        addReply(c,shared.ok);
+    } else if (c->argc == 2 && !strcasecmp(c->argv[1]->ptr,"len")) {
+        addReplyLongLong(c,listLength(server.slowlog));
+    } else if ((c->argc == 2 || c->argc == 3) &&
+               !strcasecmp(c->argv[1]->ptr,"get"))
+    {
+        long count = 10, sent = 0;
+        listIter li;
+        void *totentries;
+        listNode *ln;
+        slowlogEntry *se;
+
+        if (c->argc == 3 &&
+            getLongFromObjectOrReply(c,c->argv[2],&count,NULL) != REDIS_OK)
+            return;
+
+        listRewind(server.slowlog,&li);
+        totentries = addDeferredMultiBulkLength(c);
+        while(count-- && (ln = listNext(&li))) {
+            int j;
+
+            se = ln->value;
+            addReplyMultiBulkLen(c,4);
+            addReplyLongLong(c,se->id);
+            addReplyLongLong(c,se->time);
+            addReplyLongLong(c,se->duration);
+            addReplyMultiBulkLen(c,se->argc);
+            for (j = 0; j < se->argc; j++)
+                addReplyBulk(c,se->argv[j]);
+            sent++;
+        }
+        setDeferredMultiBulkLength(c,totentries,sent);
+    } else {
+        addReplyError(c,
+            "Unknown SLOWLOG subcommand or wrong # of args. Try GET, RESET, LEN.");
+    }
+}

src/slowlog.h

@@ -0,0 +1,15 @@
+/* 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 nanoseconds. */
+    time_t time;        /* Unix time at which the query was executed. */
+} slowlogEntry;
+
+/* Exported API */
+void slowlogInit(void);
+void slowlogPushEntryIfNeeded(robj **argv, int argc, long long duration);
+
+/* Exported commands */
+void slowlogCommand(redisClient *c);

tests/test_helper.tcl

@@ -125,6 +125,7 @@ proc execute_everything {} {
     execute_tests "integration/aof"
 #    execute_tests "integration/redis-cli"
     execute_tests "unit/pubsub"
+    execute_tests "unit/slowlog"
 
     # run tests with VM enabled
     set ::global_overrides {vm-enabled yes}

tests/unit/slowlog.tcl

@@ -0,0 +1,41 @@
+start_server {tags {"slowlog"}} {
+    test {SLOWLOG - check that it starts with an empty log} {
+        r slowlog len
+    } {0}
+
+    test {SLOWLOG - only logs commands taking more time than specified} {
+        r config set slowlog-log-slower-than 100000
+        r ping
+        assert_equal [r slowlog len] 0
+        r debug sleep 0.2
+        assert_equal [r slowlog len] 1
+    }
+
+    test {SLOWLOG - max entries is correctly handled} {
+        r config set slowlog-log-slower-than 0
+        r config set slowlog-max-len 10
+        for {set i 0} {$i < 100} {incr i} {
+            r ping
+        }
+        r slowlog len
+    } {10}
+
+    test {SLOWLOG - GET optional argument to limit output len works} {
+        llength [r slowlog get 5]
+    } {5}
+
+    test {SLOWLOG - RESET subcommand works} {
+        r config set slowlog-log-slower-than 100000
+        r slowlog reset
+        r slowlog len
+    } {0}
+
+    test {SLOWLOG - logged entry sanity check} {
+        r debug sleep 0.2
+        set e [lindex [r slowlog get] 0]
+        assert_equal [llength $e] 4
+        assert_equal [lindex $e 0] 105
+        assert_equal [expr {[lindex $e 2] > 100000}] 1
+        assert_equal [lindex $e 3] {debug sleep 0.2}
+    }
+}