From 8612e6de888fe30bd8cfcd0f4ad1979a92434a2f Mon Sep 17 00:00:00 2001 From: antirez Date: Tue, 1 Jul 2014 11:43:38 +0200 Subject: [PATCH] Latency monitor: collect slow commands. We introduce the distinction between slow and fast commands since those are two different sources of latency. An O(1) or O(log N) command without side effects (can't trigger deletion of large objects as a side effect of its execution) if delayed is a symptom of inherent latency of the system. A non-fast command (commands that may run large O(N) computations) if delayed may just mean that the user is executing slow operations. The advices LATENCY should provide in this two different cases are different, so we log the two classes of commands in a separated way. --- src/latency.h | 2 +- src/redis.c | 142 +++++++++++++++++++++++++++----------------------- src/redis.h | 1 + 3 files changed, 78 insertions(+), 67 deletions(-) diff --git a/src/latency.h b/src/latency.h index 5f5039259..cba303912 100644 --- a/src/latency.h +++ b/src/latency.h @@ -35,7 +35,7 @@ void latencyAddSample(char *event, mstime_t latency); /* Add the sample only if the elapsed time is >= to the configured threshold. */ #define latencyAddSampleIfNeeded(event,var) \ - if (server.latency_monitor_threshold && \\ + if (server.latency_monitor_threshold && \ var >= server.latency_monitor_threshold) \ latencyAddSample(event,var); diff --git a/src/redis.c b/src/redis.c index 8d6b55ed9..26e2295cb 100644 --- a/src/redis.c +++ b/src/redis.c @@ -115,48 +115,52 @@ struct redisCommand *commandTable; * M: Do not automatically propagate the command on MONITOR. * k: Perform an implicit ASKING for this command, so the command will be * accepted in cluster mode if the slot is marked as 'importing'. + * F: Fast command: O(1) or O(log(N)) command that should never delay + * its execution as long as the kernel scheduler is giving us time. + * Note that commands that may trigger a DEL as a side effect (like SET) + * are not fast commands. */ struct redisCommand redisCommandTable[] = { - {"get",getCommand,2,"r",0,NULL,1,1,1,0,0}, + {"get",getCommand,2,"rF",0,NULL,1,1,1,0,0}, {"set",setCommand,-3,"wm",0,NULL,1,1,1,0,0}, - {"setnx",setnxCommand,3,"wm",0,NULL,1,1,1,0,0}, + {"setnx",setnxCommand,3,"wmF",0,NULL,1,1,1,0,0}, {"setex",setexCommand,4,"wm",0,NULL,1,1,1,0,0}, {"psetex",psetexCommand,4,"wm",0,NULL,1,1,1,0,0}, {"append",appendCommand,3,"wm",0,NULL,1,1,1,0,0}, - {"strlen",strlenCommand,2,"r",0,NULL,1,1,1,0,0}, + {"strlen",strlenCommand,2,"rF",0,NULL,1,1,1,0,0}, {"del",delCommand,-2,"w",0,NULL,1,-1,1,0,0}, - {"exists",existsCommand,2,"r",0,NULL,1,1,1,0,0}, + {"exists",existsCommand,2,"rF",0,NULL,1,1,1,0,0}, {"setbit",setbitCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"getbit",getbitCommand,3,"r",0,NULL,1,1,1,0,0}, + {"getbit",getbitCommand,3,"rF",0,NULL,1,1,1,0,0}, {"setrange",setrangeCommand,4,"wm",0,NULL,1,1,1,0,0}, {"getrange",getrangeCommand,4,"r",0,NULL,1,1,1,0,0}, {"substr",getrangeCommand,4,"r",0,NULL,1,1,1,0,0}, - {"incr",incrCommand,2,"wm",0,NULL,1,1,1,0,0}, - {"decr",decrCommand,2,"wm",0,NULL,1,1,1,0,0}, + {"incr",incrCommand,2,"wmF",0,NULL,1,1,1,0,0}, + {"decr",decrCommand,2,"wmF",0,NULL,1,1,1,0,0}, {"mget",mgetCommand,-2,"r",0,NULL,1,-1,1,0,0}, - {"rpush",rpushCommand,-3,"wm",0,NULL,1,1,1,0,0}, - {"lpush",lpushCommand,-3,"wm",0,NULL,1,1,1,0,0}, - {"rpushx",rpushxCommand,3,"wm",0,NULL,1,1,1,0,0}, - {"lpushx",lpushxCommand,3,"wm",0,NULL,1,1,1,0,0}, + {"rpush",rpushCommand,-3,"wmF",0,NULL,1,1,1,0,0}, + {"lpush",lpushCommand,-3,"wmF",0,NULL,1,1,1,0,0}, + {"rpushx",rpushxCommand,3,"wmF",0,NULL,1,1,1,0,0}, + {"lpushx",lpushxCommand,3,"wmF",0,NULL,1,1,1,0,0}, {"linsert",linsertCommand,5,"wm",0,NULL,1,1,1,0,0}, - {"rpop",rpopCommand,2,"w",0,NULL,1,1,1,0,0}, - {"lpop",lpopCommand,2,"w",0,NULL,1,1,1,0,0}, + {"rpop",rpopCommand,2,"wF",0,NULL,1,1,1,0,0}, + {"lpop",lpopCommand,2,"wF",0,NULL,1,1,1,0,0}, {"brpop",brpopCommand,-3,"ws",0,NULL,1,1,1,0,0}, {"brpoplpush",brpoplpushCommand,4,"wms",0,NULL,1,2,1,0,0}, {"blpop",blpopCommand,-3,"ws",0,NULL,1,-2,1,0,0}, - {"llen",llenCommand,2,"r",0,NULL,1,1,1,0,0}, + {"llen",llenCommand,2,"rF",0,NULL,1,1,1,0,0}, {"lindex",lindexCommand,3,"r",0,NULL,1,1,1,0,0}, {"lset",lsetCommand,4,"wm",0,NULL,1,1,1,0,0}, {"lrange",lrangeCommand,4,"r",0,NULL,1,1,1,0,0}, {"ltrim",ltrimCommand,4,"w",0,NULL,1,1,1,0,0}, {"lrem",lremCommand,4,"w",0,NULL,1,1,1,0,0}, {"rpoplpush",rpoplpushCommand,3,"wm",0,NULL,1,2,1,0,0}, - {"sadd",saddCommand,-3,"wm",0,NULL,1,1,1,0,0}, - {"srem",sremCommand,-3,"w",0,NULL,1,1,1,0,0}, - {"smove",smoveCommand,4,"w",0,NULL,1,2,1,0,0}, - {"sismember",sismemberCommand,3,"r",0,NULL,1,1,1,0,0}, - {"scard",scardCommand,2,"r",0,NULL,1,1,1,0,0}, - {"spop",spopCommand,2,"wRs",0,NULL,1,1,1,0,0}, + {"sadd",saddCommand,-3,"wmF",0,NULL,1,1,1,0,0}, + {"srem",sremCommand,-3,"wF",0,NULL,1,1,1,0,0}, + {"smove",smoveCommand,4,"wF",0,NULL,1,2,1,0,0}, + {"sismember",sismemberCommand,3,"rF",0,NULL,1,1,1,0,0}, + {"scard",scardCommand,2,"rF",0,NULL,1,1,1,0,0}, + {"spop",spopCommand,2,"wRsF",0,NULL,1,1,1,0,0}, {"srandmember",srandmemberCommand,-2,"rR",0,NULL,1,1,1,0,0}, {"sinter",sinterCommand,-2,"rS",0,NULL,1,-1,1,0,0}, {"sinterstore",sinterstoreCommand,-3,"wm",0,NULL,1,-1,1,0,0}, @@ -166,9 +170,9 @@ struct redisCommand redisCommandTable[] = { {"sdiffstore",sdiffstoreCommand,-3,"wm",0,NULL,1,-1,1,0,0}, {"smembers",sinterCommand,2,"rS",0,NULL,1,1,1,0,0}, {"sscan",sscanCommand,-3,"rR",0,NULL,1,1,1,0,0}, - {"zadd",zaddCommand,-4,"wm",0,NULL,1,1,1,0,0}, - {"zincrby",zincrbyCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"zrem",zremCommand,-3,"w",0,NULL,1,1,1,0,0}, + {"zadd",zaddCommand,-4,"wmF",0,NULL,1,1,1,0,0}, + {"zincrby",zincrbyCommand,4,"wmF",0,NULL,1,1,1,0,0}, + {"zrem",zremCommand,-3,"wF",0,NULL,1,1,1,0,0}, {"zremrangebyscore",zremrangebyscoreCommand,4,"w",0,NULL,1,1,1,0,0}, {"zremrangebyrank",zremrangebyrankCommand,4,"w",0,NULL,1,1,1,0,0}, {"zremrangebylex",zremrangebylexCommand,4,"w",0,NULL,1,1,1,0,0}, @@ -179,58 +183,58 @@ struct redisCommand redisCommandTable[] = { {"zrevrangebyscore",zrevrangebyscoreCommand,-4,"r",0,NULL,1,1,1,0,0}, {"zrangebylex",zrangebylexCommand,-4,"r",0,NULL,1,1,1,0,0}, {"zrevrangebylex",zrevrangebylexCommand,-4,"r",0,NULL,1,1,1,0,0}, - {"zcount",zcountCommand,4,"r",0,NULL,1,1,1,0,0}, - {"zlexcount",zlexcountCommand,4,"r",0,NULL,1,1,1,0,0}, + {"zcount",zcountCommand,4,"rF",0,NULL,1,1,1,0,0}, + {"zlexcount",zlexcountCommand,4,"rF",0,NULL,1,1,1,0,0}, {"zrevrange",zrevrangeCommand,-4,"r",0,NULL,1,1,1,0,0}, - {"zcard",zcardCommand,2,"r",0,NULL,1,1,1,0,0}, - {"zscore",zscoreCommand,3,"r",0,NULL,1,1,1,0,0}, - {"zrank",zrankCommand,3,"r",0,NULL,1,1,1,0,0}, - {"zrevrank",zrevrankCommand,3,"r",0,NULL,1,1,1,0,0}, + {"zcard",zcardCommand,2,"rF",0,NULL,1,1,1,0,0}, + {"zscore",zscoreCommand,3,"rF",0,NULL,1,1,1,0,0}, + {"zrank",zrankCommand,3,"rF",0,NULL,1,1,1,0,0}, + {"zrevrank",zrevrankCommand,3,"rF",0,NULL,1,1,1,0,0}, {"zscan",zscanCommand,-3,"rR",0,NULL,1,1,1,0,0}, - {"hset",hsetCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"hsetnx",hsetnxCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"hget",hgetCommand,3,"r",0,NULL,1,1,1,0,0}, + {"hset",hsetCommand,4,"wmF",0,NULL,1,1,1,0,0}, + {"hsetnx",hsetnxCommand,4,"wmF",0,NULL,1,1,1,0,0}, + {"hget",hgetCommand,3,"rF",0,NULL,1,1,1,0,0}, {"hmset",hmsetCommand,-4,"wm",0,NULL,1,1,1,0,0}, {"hmget",hmgetCommand,-3,"r",0,NULL,1,1,1,0,0}, - {"hincrby",hincrbyCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"hincrbyfloat",hincrbyfloatCommand,4,"wm",0,NULL,1,1,1,0,0}, - {"hdel",hdelCommand,-3,"w",0,NULL,1,1,1,0,0}, - {"hlen",hlenCommand,2,"r",0,NULL,1,1,1,0,0}, + {"hincrby",hincrbyCommand,4,"wmF",0,NULL,1,1,1,0,0}, + {"hincrbyfloat",hincrbyfloatCommand,4,"wmF",0,NULL,1,1,1,0,0}, + {"hdel",hdelCommand,-3,"wF",0,NULL,1,1,1,0,0}, + {"hlen",hlenCommand,2,"rF",0,NULL,1,1,1,0,0}, {"hkeys",hkeysCommand,2,"rS",0,NULL,1,1,1,0,0}, {"hvals",hvalsCommand,2,"rS",0,NULL,1,1,1,0,0}, {"hgetall",hgetallCommand,2,"r",0,NULL,1,1,1,0,0}, - {"hexists",hexistsCommand,3,"r",0,NULL,1,1,1,0,0}, + {"hexists",hexistsCommand,3,"rF",0,NULL,1,1,1,0,0}, {"hscan",hscanCommand,-3,"rR",0,NULL,1,1,1,0,0}, - {"incrby",incrbyCommand,3,"wm",0,NULL,1,1,1,0,0}, - {"decrby",decrbyCommand,3,"wm",0,NULL,1,1,1,0,0}, - {"incrbyfloat",incrbyfloatCommand,3,"wm",0,NULL,1,1,1,0,0}, + {"incrby",incrbyCommand,3,"wmF",0,NULL,1,1,1,0,0}, + {"decrby",decrbyCommand,3,"wmF",0,NULL,1,1,1,0,0}, + {"incrbyfloat",incrbyfloatCommand,3,"wmF",0,NULL,1,1,1,0,0}, {"getset",getsetCommand,3,"wm",0,NULL,1,1,1,0,0}, {"mset",msetCommand,-3,"wm",0,NULL,1,-1,2,0,0}, {"msetnx",msetnxCommand,-3,"wm",0,NULL,1,-1,2,0,0}, {"randomkey",randomkeyCommand,1,"rR",0,NULL,0,0,0,0,0}, - {"select",selectCommand,2,"rl",0,NULL,0,0,0,0,0}, - {"move",moveCommand,3,"w",0,NULL,1,1,1,0,0}, + {"select",selectCommand,2,"rlF",0,NULL,0,0,0,0,0}, + {"move",moveCommand,3,"wF",0,NULL,1,1,1,0,0}, {"rename",renameCommand,3,"w",0,NULL,1,2,1,0,0}, - {"renamenx",renamenxCommand,3,"w",0,NULL,1,2,1,0,0}, - {"expire",expireCommand,3,"w",0,NULL,1,1,1,0,0}, - {"expireat",expireatCommand,3,"w",0,NULL,1,1,1,0,0}, - {"pexpire",pexpireCommand,3,"w",0,NULL,1,1,1,0,0}, - {"pexpireat",pexpireatCommand,3,"w",0,NULL,1,1,1,0,0}, + {"renamenx",renamenxCommand,3,"wF",0,NULL,1,2,1,0,0}, + {"expire",expireCommand,3,"wF",0,NULL,1,1,1,0,0}, + {"expireat",expireatCommand,3,"wF",0,NULL,1,1,1,0,0}, + {"pexpire",pexpireCommand,3,"wF",0,NULL,1,1,1,0,0}, + {"pexpireat",pexpireatCommand,3,"wF",0,NULL,1,1,1,0,0}, {"keys",keysCommand,2,"rS",0,NULL,0,0,0,0,0}, {"scan",scanCommand,-2,"rR",0,NULL,0,0,0,0,0}, - {"dbsize",dbsizeCommand,1,"r",0,NULL,0,0,0,0,0}, - {"auth",authCommand,2,"rslt",0,NULL,0,0,0,0,0}, - {"ping",pingCommand,1,"rt",0,NULL,0,0,0,0,0}, - {"echo",echoCommand,2,"r",0,NULL,0,0,0,0,0}, + {"dbsize",dbsizeCommand,1,"rF",0,NULL,0,0,0,0,0}, + {"auth",authCommand,2,"rsltF",0,NULL,0,0,0,0,0}, + {"ping",pingCommand,1,"rtF",0,NULL,0,0,0,0,0}, + {"echo",echoCommand,2,"rF",0,NULL,0,0,0,0,0}, {"save",saveCommand,1,"ars",0,NULL,0,0,0,0,0}, {"bgsave",bgsaveCommand,1,"ar",0,NULL,0,0,0,0,0}, {"bgrewriteaof",bgrewriteaofCommand,1,"ar",0,NULL,0,0,0,0,0}, {"shutdown",shutdownCommand,-1,"arlt",0,NULL,0,0,0,0,0}, - {"lastsave",lastsaveCommand,1,"rR",0,NULL,0,0,0,0,0}, - {"type",typeCommand,2,"r",0,NULL,1,1,1,0,0}, - {"multi",multiCommand,1,"rs",0,NULL,0,0,0,0,0}, + {"lastsave",lastsaveCommand,1,"rRF",0,NULL,0,0,0,0,0}, + {"type",typeCommand,2,"rF",0,NULL,1,1,1,0,0}, + {"multi",multiCommand,1,"rsF",0,NULL,0,0,0,0,0}, {"exec",execCommand,1,"sM",0,NULL,0,0,0,0,0}, - {"discard",discardCommand,1,"rs",0,NULL,0,0,0,0,0}, + {"discard",discardCommand,1,"rsF",0,NULL,0,0,0,0,0}, {"sync",syncCommand,1,"ars",0,NULL,0,0,0,0,0}, {"psync",syncCommand,3,"ars",0,NULL,0,0,0,0,0}, {"replconf",replconfCommand,-1,"arslt",0,NULL,0,0,0,0,0}, @@ -239,9 +243,9 @@ struct redisCommand redisCommandTable[] = { {"sort",sortCommand,-2,"wm",0,sortGetKeys,1,1,1,0,0}, {"info",infoCommand,-1,"rlt",0,NULL,0,0,0,0,0}, {"monitor",monitorCommand,1,"ars",0,NULL,0,0,0,0,0}, - {"ttl",ttlCommand,2,"r",0,NULL,1,1,1,0,0}, - {"pttl",pttlCommand,2,"r",0,NULL,1,1,1,0,0}, - {"persist",persistCommand,2,"w",0,NULL,1,1,1,0,0}, + {"ttl",ttlCommand,2,"rF",0,NULL,1,1,1,0,0}, + {"pttl",pttlCommand,2,"rF",0,NULL,1,1,1,0,0}, + {"persist",persistCommand,2,"wF",0,NULL,1,1,1,0,0}, {"slaveof",slaveofCommand,3,"ast",0,NULL,0,0,0,0,0}, {"role",roleCommand,1,"last",0,NULL,0,0,0,0,0}, {"debug",debugCommand,-2,"as",0,NULL,0,0,0,0,0}, @@ -250,17 +254,17 @@ struct redisCommand redisCommandTable[] = { {"unsubscribe",unsubscribeCommand,-1,"rpslt",0,NULL,0,0,0,0,0}, {"psubscribe",psubscribeCommand,-2,"rpslt",0,NULL,0,0,0,0,0}, {"punsubscribe",punsubscribeCommand,-1,"rpslt",0,NULL,0,0,0,0,0}, - {"publish",publishCommand,3,"pltr",0,NULL,0,0,0,0,0}, + {"publish",publishCommand,3,"pltrF",0,NULL,0,0,0,0,0}, {"pubsub",pubsubCommand,-2,"pltrR",0,NULL,0,0,0,0,0}, - {"watch",watchCommand,-2,"rs",0,NULL,1,-1,1,0,0}, - {"unwatch",unwatchCommand,1,"rs",0,NULL,0,0,0,0,0}, + {"watch",watchCommand,-2,"rsF",0,NULL,1,-1,1,0,0}, + {"unwatch",unwatchCommand,1,"rsF",0,NULL,0,0,0,0,0}, {"cluster",clusterCommand,-2,"ar",0,NULL,0,0,0,0,0}, {"restore",restoreCommand,-4,"awm",0,NULL,1,1,1,0,0}, {"restore-asking",restoreCommand,-4,"awmk",0,NULL,1,1,1,0,0}, {"migrate",migrateCommand,-6,"aw",0,NULL,0,0,0,0,0}, {"asking",askingCommand,1,"r",0,NULL,0,0,0,0,0}, - {"readonly",readonlyCommand,1,"r",0,NULL,0,0,0,0,0}, - {"readwrite",readwriteCommand,1,"r",0,NULL,0,0,0,0,0}, + {"readonly",readonlyCommand,1,"rF",0,NULL,0,0,0,0,0}, + {"readwrite",readwriteCommand,1,"rF",0,NULL,0,0,0,0,0}, {"dump",dumpCommand,2,"ar",0,NULL,1,1,1,0,0}, {"object",objectCommand,-2,"r",0,NULL,2,2,2,0,0}, {"client",clientCommand,-2,"ar",0,NULL,0,0,0,0,0}, @@ -268,14 +272,14 @@ struct redisCommand redisCommandTable[] = { {"evalsha",evalShaCommand,-3,"s",0,evalGetKeys,0,0,0,0,0}, {"slowlog",slowlogCommand,-2,"r",0,NULL,0,0,0,0,0}, {"script",scriptCommand,-2,"ras",0,NULL,0,0,0,0,0}, - {"time",timeCommand,1,"rR",0,NULL,0,0,0,0,0}, + {"time",timeCommand,1,"rRF",0,NULL,0,0,0,0,0}, {"bitop",bitopCommand,-4,"wm",0,NULL,2,-1,1,0,0}, {"bitcount",bitcountCommand,-2,"r",0,NULL,1,1,1,0,0}, {"bitpos",bitposCommand,-3,"r",0,NULL,1,1,1,0,0}, {"wait",waitCommand,3,"rs",0,NULL,0,0,0,0,0}, {"command",commandCommand,0,"rlt",0,NULL,0,0,0,0,0}, {"pfselftest",pfselftestCommand,1,"r",0,NULL,0,0,0,0,0}, - {"pfadd",pfaddCommand,-2,"wm",0,NULL,1,1,1,0,0}, + {"pfadd",pfaddCommand,-2,"wmF",0,NULL,1,1,1,0,0}, {"pfcount",pfcountCommand,-2,"w",0,NULL,1,1,1,0,0}, {"pfmerge",pfmergeCommand,-2,"wm",0,NULL,1,-1,1,0,0}, {"pfdebug",pfdebugCommand,-3,"w",0,NULL,0,0,0,0,0} @@ -1853,6 +1857,7 @@ void populateCommandTable(void) { case 't': c->flags |= REDIS_CMD_STALE; break; case 'M': c->flags |= REDIS_CMD_SKIP_MONITOR; break; case 'k': c->flags |= REDIS_CMD_ASKING; break; + case 'F': c->flags |= REDIS_CMD_FAST; break; default: redisPanic("Unsupported command flag"); break; } f++; @@ -2017,8 +2022,12 @@ void call(redisClient *c, int flags) { /* Log the command into the Slow log if needed, and populate the * per-command statistics that we show in INFO commandstats. */ - if (flags & REDIS_CALL_SLOWLOG && c->cmd->proc != execCommand) + if (flags & REDIS_CALL_SLOWLOG && c->cmd->proc != execCommand) { + char *latency_event = (c->cmd->flags & REDIS_CMD_FAST) ? + "fast-command" : "command"; + latencyAddSampleIfNeeded(latency_event,duration); slowlogPushEntryIfNeeded(c->argv,c->argc,duration); + } if (flags & REDIS_CALL_STATS) { c->cmd->microseconds += duration; c->cmd->calls++; @@ -2440,6 +2449,7 @@ void addReplyCommand(redisClient *c, struct redisCommand *cmd) { flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_STALE, "stale"); flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_SKIP_MONITOR, "skip_monitor"); flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_ASKING, "asking"); + flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_FAST, "fast"); if (cmd->getkeys_proc) { addReplyStatus(c, "movablekeys"); flagcount += 1; diff --git a/src/redis.h b/src/redis.h index cf22a09b4..1d33e5594 100644 --- a/src/redis.h +++ b/src/redis.h @@ -166,6 +166,7 @@ typedef long long mstime_t; /* millisecond time type. */ #define REDIS_CMD_STALE 1024 /* "t" flag */ #define REDIS_CMD_SKIP_MONITOR 2048 /* "M" flag */ #define REDIS_CMD_ASKING 4096 /* "k" flag */ +#define REDIS_CMD_FAST 8192 /* "F" flag */ /* Object types */ #define REDIS_STRING 0