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.
This commit is contained in:
antirez 2014-07-01 11:43:38 +02:00
parent d7a07a2012
commit 8612e6de88
3 changed files with 78 additions and 67 deletions

View File

@ -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);

View File

@ -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;

View File

@ -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