diff --git a/deps/hiredis/hiredis.c b/deps/hiredis/hiredis.c index d4cad7c2..1bddafb6 100644 --- a/deps/hiredis/hiredis.c +++ b/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; } diff --git a/redis.conf b/redis.conf index b0332ea4..a545b78b 100644 --- a/redis.conf +++ b/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 diff --git a/src/Makefile b/src/Makefile index 17fc435b..c08d50c3 100644 --- a/src/Makefile +++ b/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}") diff --git a/src/config.c b/src/config.c index 022e8fd5..44c0e21d 100644 --- a/src/config.c +++ b/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); } diff --git a/src/debug.c b/src/debug.c index 30ae08e6..9b28645b 100644 --- a/src/debug.c +++ b/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 |SWAPIN |SWAPOUT |RELOAD]"); diff --git a/src/redis.c b/src/redis.c index 45be8937..0ea7813a 100644 --- a/src/redis.c +++ b/src/redis.c @@ -28,6 +28,7 @@ */ #include "redis.h" +#include "slowlog.h" #ifdef HAVE_BACKTRACE #include @@ -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); diff --git a/src/redis.h b/src/redis.h index 7dcca3be..70d20db4 100644 --- a/src/redis.h +++ b/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; diff --git a/src/slowlog.c b/src/slowlog.c new file mode 100644 index 00000000..cfd66dc6 --- /dev/null +++ b/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."); + } +} diff --git a/src/slowlog.h b/src/slowlog.h new file mode 100644 index 00000000..bad770db --- /dev/null +++ b/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); diff --git a/tests/test_helper.tcl b/tests/test_helper.tcl index 5e12e05d..9b1ba634 100644 --- a/tests/test_helper.tcl +++ b/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} diff --git a/tests/unit/slowlog.tcl b/tests/unit/slowlog.tcl new file mode 100644 index 00000000..d7fca782 --- /dev/null +++ b/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} + } +}