First implementation of the slow log feature

src/Makefile

@@ -61,7 +61,7 @@ QUIET_CC = @printf '    %b %b\n' $(CCCOLOR)CC$(ENDCOLOR) $(SRCCOLOR)$@$(ENDCOLOR
 QUIET_LINK = @printf '    %b %b\n' $(LINKCOLOR)LINK$(ENDCOLOR) $(BINCOLOR)$@$(ENDCOLOR);
 endif
 
-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 pubsub.o multi.o debug.o sort.o intset.o syncio.o cluster.o crc16.o endian.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 pubsub.o multi.o debug.o sort.o intset.o syncio.o cluster.o crc16.o endian.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
@@ -86,38 +86,37 @@ ae_kqueue.o: ae_kqueue.c
 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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 cluster.o: cluster.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 util.h
-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 util.h
-crc16.o: crc16.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 util.h
-db.o: db.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 util.h
-debug.o: debug.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 util.h sha1.h
-dict.o: dict.c fmacros.h dict.h zmalloc.h
-diskstore.o: diskstore.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 util.h \
+  slowlog.h
+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 util.h slowlog.h
+crc16.o: crc16.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 util.h slowlog.h
+db.o: db.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 util.h slowlog.h
+debug.o: debug.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 util.h slowlog.h \
   sha1.h
-dscache.o: dscache.c redis.h fmacros.h config.h ae.h sds.h dict.h \
+dict.o: dict.c fmacros.h dict.h zmalloc.h
-  adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h
 endian.o: endian.c
 intset.o: intset.c intset.h zmalloc.h endian.h
 lzf_c.o: lzf_c.c lzfP.h
 lzf_d.o: lzf_d.c lzfP.h
 multi.o: multi.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 networking.o: networking.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 util.h
+  adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h \
+  slowlog.h
 object.o: object.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 pqsort.o: pqsort.c
 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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.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 util.h lzf.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h \
+  lzf.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
@@ -125,27 +124,33 @@ redis-check-dump.o: redis-check-dump.c lzf.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 util.h \
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h \
   asciilogo.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 util.h
+  adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h \
+  slowlog.h
 sds.o: sds.c sds.h zmalloc.h
 sha1.o: sha1.c sha1.h config.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 util.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 util.h pqsort.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h \
+  pqsort.h
 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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 t_list.o: t_list.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 t_set.o: t_set.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 t_string.o: t_string.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 util.h
+  adlist.h zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h \
+  slowlog.h
 t_zset.o: t_zset.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 util.h
+  zmalloc.h anet.h zipmap.h ziplist.h intset.h version.h util.h slowlog.h
 util.o: util.c fmacros.h util.h
 ziplist.o: ziplist.c zmalloc.h util.h ziplist.h endian.h
 zipmap.o: zipmap.c zmalloc.h endian.h

src/redis.c

@@ -28,6 +28,7 @@
  */
 
 #include "redis.h"
+#include "slowlog.h"
 
 #ifdef HAVE_BACKTRACE
 #include <execinfo.h>
@@ -192,7 +193,8 @@ struct redisCommand redisCommandTable[] = {
     {"migrate",migrateCommand,6,0,NULL,0,0,0,0,0},
     {"dump",dumpCommand,2,0,NULL,0,0,0,0,0},
     {"object",objectCommand,-2,0,NULL,0,0,0,0,0},
-    {"client",clientCommand,-2,0,NULL,0,0,0,0,0}
+    {"client",clientCommand,-2,0,NULL,0,0,0,0,0},
+    {"slowlog",slowlogCommand,-2,0,NULL,0,0,0,0,0}
 };
 
 /*============================ Utility functions ============================ */
@@ -866,6 +868,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() {
@@ -952,6 +958,7 @@ void initServer() {
     }
 
     if (server.cluster_enabled) clusterInit();
+    slowlogInit();
     srand(time(NULL)^getpid());
 }
 
@@ -999,12 +1006,14 @@ 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, start = ustime();
+    long long dirty, start = ustime(), duration;
 
     dirty = server.dirty;
     cmd->proc(c);
     dirty = server.dirty-dirty;
-    cmd->microseconds += ustime()-start;
+    duration = ustime()-start;
+    cmd->microseconds += duration;
+    slowlogPushEntryIfNeeded(c->argv,c->argc,duration);
     cmd->calls++;
 
     if (server.appendonly && dirty)

src/redis.h

@@ -20,17 +20,17 @@
 #include <syslog.h>
 #include <netinet/in.h>
 
-#include "ae.h"     /* Event driven programming library */
+#include "ae.h"      /* Event driven programming library */
-#include "sds.h"    /* Dynamic safe strings */
+#include "sds.h"     /* Dynamic safe strings */
-#include "dict.h"   /* Hash tables */
+#include "dict.h"    /* Hash tables */
-#include "adlist.h" /* Linked lists */
+#include "adlist.h"  /* Linked lists */
 #include "zmalloc.h" /* total memory usage aware version of malloc/free */
-#include "anet.h"   /* Networking the easy way */
+#include "anet.h"    /* Networking the easy way */
-#include "zipmap.h" /* Compact string -> string data structure */
+#include "zipmap.h"  /* Compact string -> string data structure */
 #include "ziplist.h" /* Compact list data structure */
-#include "intset.h" /* Compact integer set structure */
+#include "intset.h"  /* Compact integer set structure */
-#include "version.h"
+#include "version.h" /* Version macro */
-#include "util.h"
+#include "util.h"    /* Misc functions useful in many places */
 
 /* Error codes */
 #define REDIS_OK                0
@@ -52,6 +52,8 @@
 #define REDIS_MAX_LOGMSG_LEN    1024 /* Default maximum length of syslog messages */
 #define REDIS_AUTO_AOFREWRITE_PERC  100
 #define REDIS_AUTO_AOFREWRITE_MIN_SIZE (1024*1024)
+#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% */
@@ -525,6 +527,9 @@ struct redisServer {
     long long stat_keyspace_misses; /* number of failed lookups of keys */
     size_t stat_peak_memory;        /* max used memory record */
     long long stat_fork_time;       /* time needed to perform latets fork() */
+    list *slowlog;
+    long long slowlog_log_slower_than;
+    unsigned int slowlog_max_len;
     /* Configuration */
     int verbosity;
     int maxidletime;

src/slowlog.c

@@ -0,0 +1,111 @@
+#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;
+    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();
+    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 (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,3);
+            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,14 @@
+/* This structure defines an entry inside the slow log list */
+typedef struct slowlogEntry {
+    robj **argv;
+    int argc;
+    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);