From 72c84acc9997d639b6acdd6c9ef054ba9a6f85d7 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 | 148 +++++++++++++++++++++++++++----------------------- src/redis.h | 2 + 3 files changed, 82 insertions(+), 70 deletions(-) diff --git a/src/latency.h b/src/latency.h index 5f503925..cba30391 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 8308cf91..ac544095 100644 --- a/src/redis.c +++ b/src/redis.c @@ -112,48 +112,52 @@ struct redisCommand *commandTable; * server this data. Normally no command is accepted in this condition * but just a few. * M: Do not automatically propagate the command on MONITOR. + * 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}, - {"set",setCommand,-3,"wm",0,noPreloadGetKeys,1,1,1,0,0}, - {"setnx",setnxCommand,3,"wm",0,noPreloadGetKeys,1,1,1,0,0}, - {"setex",setexCommand,4,"wm",0,noPreloadGetKeys,1,1,1,0,0}, - {"psetex",psetexCommand,4,"wm",0,noPreloadGetKeys,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,"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}, - {"del",delCommand,-2,"w",0,noPreloadGetKeys,1,-1,1,0,0}, - {"exists",existsCommand,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,"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}, @@ -163,9 +167,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}, @@ -176,58 +180,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}, - {"rename",renameCommand,3,"w",0,renameGetKeys,1,2,1,0,0}, - {"renamenx",renamenxCommand,3,"w",0,renameGetKeys,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}, + {"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,"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}, @@ -236,9 +240,9 @@ struct redisCommand redisCommandTable[] = { {"sort",sortCommand,-2,"wm",0,NULL,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}, @@ -247,10 +251,10 @@ 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,noPreloadGetKeys,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}, {"restore",restoreCommand,4,"awm",0,NULL,1,1,1,0,0}, {"migrate",migrateCommand,6,"aw",0,NULL,0,0,0,0,0}, {"dump",dumpCommand,2,"ar",0,NULL,1,1,1,0,0}, @@ -260,13 +264,13 @@ struct redisCommand redisCommandTable[] = { {"evalsha",evalShaCommand,-3,"s",0,zunionInterGetKeys,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}, {"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} @@ -1761,6 +1765,7 @@ void populateCommandTable(void) { case 'l': c->flags |= REDIS_CMD_LOADING; break; case 't': c->flags |= REDIS_CMD_STALE; break; case 'M': c->flags |= REDIS_CMD_SKIP_MONITOR; break; + case 'F': c->flags |= REDIS_CMD_FAST; break; default: redisPanic("Unsupported command flag"); break; } f++; @@ -1925,8 +1930,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++; @@ -2303,6 +2312,7 @@ void addReplyCommand(redisClient *c, struct redisCommand *cmd) { flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_LOADING, "loading"); flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_STALE, "stale"); flagcount += addReplyCommandFlag(c,cmd,REDIS_CMD_SKIP_MONITOR, "skip_monitor"); + 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 8a1babb0..44e0bbe5 100644 --- a/src/redis.h +++ b/src/redis.h @@ -165,6 +165,8 @@ typedef long long mstime_t; /* millisecond time type. */ #define REDIS_CMD_LOADING 512 /* "l" flag */ #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