slow log merged into 2.4

src/Makefile

@@ -58,7 +58,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
@@ -113,12 +113,15 @@ 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 help.h sds.c sds.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 redis.h fmacros.h config.h ae.h sds.h dict.h adlist.h \
@@ -191,7 +194,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

@@ -309,6 +309,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;
         }
@@ -489,6 +495,12 @@ void configSetCommand(redisClient *c) {
     } else if (!strcasecmp(c->argv[2]->ptr,"zset-max-ziplist-value")) {
         if (getLongLongFromObject(o,&ll) == REDIS_ERR || ll < 0) goto badfmt;
         server.zset_max_ziplist_value = 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);
@@ -660,6 +672,16 @@ void configGetCommand(redisClient *c) {
         addReplyBulkLongLong(c,server.zset_max_ziplist_value);
         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

@@ -324,6 +324,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>
@@ -189,7 +190,8 @@ struct redisCommand readonlyCommandTable[] = {
     {"watch",watchCommand,-2,0,NULL,0,0,0},
     {"unwatch",unwatchCommand,1,0,NULL,0,0,0},
     {"object",objectCommand,-2,0,NULL,0,0,0},
-    {"client",clientCommand,-2,0,NULL,0,0,0}
+    {"client",clientCommand,-2,0,NULL,0,0,0},
+    {"slowlog",slowlogCommand,-2,0,NULL,0,0,0}
 };
 
 /*============================ Utility functions ============================ */
@@ -868,6 +870,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() {
@@ -956,6 +962,7 @@ void initServer() {
     }
 
     if (server.vm_enabled) vmInit();
+    slowlogInit();
     srand(time(NULL)^getpid());
 }
 
@@ -991,11 +998,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

@@ -51,6 +51,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% */
@@ -402,8 +404,15 @@ 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 */
+<<<<<<< HEAD
     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_entry_id;
+    long long slowlog_log_slower_than;
+    unsigned long slowlog_max_len;
+>>>>>>> ad6347b... Slowlog backported to 2.2
     /* 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);