From f0c5052aa8de084f54b3eda7848f17b122907509 Mon Sep 17 00:00:00 2001 From: filipe oliveira Date: Fri, 29 Jan 2021 13:38:30 +0000 Subject: [PATCH] Enabled background and reply time tracking on blocked on keys/blocked on background work clients (#7491) This commit enables tracking time of the background tasks and on replies, opening the door for properly tracking commands that rely on blocking / background work via the slowlog, latency history, and commandstats. Some notes: - The time spent blocked waiting for key changes, or blocked on synchronous replication is not accounted for. - **This commit does not affect latency tracking of commands that are non-blocking or do not have background work.** ( meaning that it all stays the same with exception to `BZPOPMIN`,`BZPOPMAX`,`BRPOP`,`BLPOP`, etc... and module's commands that rely on background threads ). - Specifically for latency history command we've added a new event class named `command-unblocking` that will enable latency monitoring on commands that spawn background threads to do the work. - For blocking commands we're now considering the total time of a command as the time spent on call() + the time spent on replying when unblocked. - For Modules commands that rely on background threads we're now considering the total time of a command as the time spent on call (main thread) + the time spent on the background thread ( if marked within `RedisModule_MeasureTimeStart()` and `RedisModule_MeasureTimeEnd()` ) + the time spent on replying (main thread) To test for this feature we've added a `unit/moduleapi/blockonbackground` test that relies on a module that blocks the client and sleeps on the background for a given time. - check blocked command that uses RedisModule_MeasureTimeStart() is tracking background time - check blocked command that uses RedisModule_MeasureTimeStart() is tracking background time even in timeout - check blocked command with multiple calls RedisModule_MeasureTimeStart() is tracking the total background time - check blocked command without calling RedisModule_MeasureTimeStart() is not reporting background time --- runtest-moduleapi | 1 + src/blocked.c | 29 +++ src/module.c | 51 +++++ src/redismodule.h | 4 + src/server.c | 12 +- src/server.h | 2 + tests/modules/Makefile | 1 + tests/modules/blockonbackground.c | 220 +++++++++++++++++++++ tests/unit/moduleapi/blockonbackground.tcl | 67 +++++++ 9 files changed, 383 insertions(+), 4 deletions(-) create mode 100644 tests/modules/blockonbackground.c create mode 100644 tests/unit/moduleapi/blockonbackground.tcl diff --git a/runtest-moduleapi b/runtest-moduleapi index 878b5c6ad..e554226c1 100755 --- a/runtest-moduleapi +++ b/runtest-moduleapi @@ -23,6 +23,7 @@ $TCLSH tests/test_helper.tcl \ --single unit/moduleapi/hooks \ --single unit/moduleapi/misc \ --single unit/moduleapi/blockonkeys \ +--single unit/moduleapi/blockonbackground \ --single unit/moduleapi/scan \ --single unit/moduleapi/datatype \ --single unit/moduleapi/auth \ diff --git a/src/blocked.c b/src/blocked.c index 1d69ff902..09e17213c 100644 --- a/src/blocked.c +++ b/src/blocked.c @@ -61,6 +61,9 @@ */ #include "server.h" +#include "slowlog.h" +#include "latency.h" +#include "monotonic.h" int serveClientBlockedOnList(client *receiver, robj *key, robj *dstkey, redisDb *db, robj *value, int wherefrom, int whereto); int getListPositionFromObjectOrReply(client *c, robj *arg, int *position); @@ -97,6 +100,20 @@ void blockClient(client *c, int btype) { } } +/* This function is called after a client has finished a blocking operation + * in order to update the total command duration, log the command into + * the Slow log if needed, and log the reply duration event if needed. */ +void updateStatsOnUnblock(client *c, long blocked_us, long reply_us){ + const ustime_t total_cmd_duration = c->duration + blocked_us + reply_us; + c->lastcmd->microseconds += total_cmd_duration; + /* Log the command into the Slow log if needed. */ + if (!(c->lastcmd->flags & CMD_SKIP_SLOWLOG)) { + slowlogPushEntryIfNeeded(c,c->argv,c->argc,total_cmd_duration); + /* Log the reply duration event. */ + latencyAddSampleIfNeeded("command-unblocking",reply_us/1000); + } +} + /* This function is called in the beforeSleep() function of the event loop * in order to process the pending input buffer of clients that were * unblocked after a blocking operation. */ @@ -264,6 +281,8 @@ void serveClientsBlockedOnListKey(robj *o, readyList *rl) { if (dstkey) incrRefCount(dstkey); unblockClient(receiver); + monotime replyTimer; + elapsedStart(&replyTimer); if (serveClientBlockedOnList(receiver, rl->key,dstkey,rl->db,value, wherefrom, whereto) == C_ERR) @@ -272,6 +291,7 @@ void serveClientsBlockedOnListKey(robj *o, readyList *rl) { * to also undo the POP operation. */ listTypePush(o,value,wherefrom); } + updateStatsOnUnblock(receiver, 0, elapsedUs(replyTimer)); if (dstkey) decrRefCount(dstkey); decrRefCount(value); @@ -316,7 +336,10 @@ void serveClientsBlockedOnSortedSetKey(robj *o, readyList *rl) { receiver->lastcmd->proc == bzpopminCommand) ? ZSET_MIN : ZSET_MAX; unblockClient(receiver); + monotime replyTimer; + elapsedStart(&replyTimer); genericZpopCommand(receiver,&rl->key,1,where,1,NULL); + updateStatsOnUnblock(receiver, 0, elapsedUs(replyTimer)); zcard--; /* Replicate the command. */ @@ -406,6 +429,8 @@ void serveClientsBlockedOnStreamKey(robj *o, readyList *rl) { } } + monotime replyTimer; + elapsedStart(&replyTimer); /* Emit the two elements sub-array consisting of * the name of the stream and the data we * extracted from it. Wrapped in a single-item @@ -425,6 +450,7 @@ void serveClientsBlockedOnStreamKey(robj *o, readyList *rl) { streamReplyWithRange(receiver,s,&start,NULL, receiver->bpop.xread_count, 0, group, consumer, noack, &pi); + updateStatsOnUnblock(receiver, 0, elapsedUs(replyTimer)); /* Note that after we unblock the client, 'gt' * and other receiver->bpop stuff are no longer @@ -471,7 +497,10 @@ void serveClientsBlockedOnKeyByModule(readyList *rl) { * different modules with different triggers to consider if a key * is ready or not. This means we can't exit the loop but need * to continue after the first failure. */ + monotime replyTimer; + elapsedStart(&replyTimer); if (!moduleTryServeClientBlockedOnKey(receiver, rl->key)) continue; + updateStatsOnUnblock(receiver, 0, elapsedUs(replyTimer)); moduleUnblockClient(receiver); } diff --git a/src/module.c b/src/module.c index f3191bbc7..b04595801 100644 --- a/src/module.c +++ b/src/module.c @@ -29,7 +29,9 @@ #include "server.h" #include "cluster.h" +#include "slowlog.h" #include "rdb.h" +#include "monotonic.h" #include #include #include @@ -262,6 +264,9 @@ typedef struct RedisModuleBlockedClient { int dbid; /* Database number selected by the original client. */ int blocked_on_keys; /* If blocked via RM_BlockClientOnKeys(). */ int unblocked; /* Already on the moduleUnblocked list. */ + monotime background_timer; /* Timer tracking the start of background work */ + uint64_t background_duration; /* Current command background time duration. + Used for measuring latency of blocking cmds */ } RedisModuleBlockedClient; static pthread_mutex_t moduleUnblockedClientsMutex = PTHREAD_MUTEX_INITIALIZER; @@ -915,6 +920,30 @@ long long RM_Milliseconds(void) { return mstime(); } +/* Mark a point in time that will be used as the start time to calculate + * the elapsed execution time when RM_BlockedClientMeasureTimeEnd() is called. + * Within the same command, you can call multiple times + * RM_BlockedClientMeasureTimeStart() and RM_BlockedClientMeasureTimeEnd() + * to accummulate indepedent time intervals to the background duration. + * This method always return REDISMODULE_OK. */ +int RM_BlockedClientMeasureTimeStart(RedisModuleBlockedClient *bc) { + elapsedStart(&(bc->background_timer)); + return REDISMODULE_OK; +} + +/* Mark a point in time that will be used as the end time + * to calculate the elapsed execution time. + * On success REDISMODULE_OK is returned. + * This method only returns REDISMODULE_ERR if no start time was + * previously defined ( meaning RM_BlockedClientMeasureTimeStart was not called ). */ +int RM_BlockedClientMeasureTimeEnd(RedisModuleBlockedClient *bc) { + // If the counter is 0 then we haven't called RM_BlockedClientMeasureTimeStart + if (!bc->background_timer) + return REDISMODULE_ERR; + bc->background_duration += elapsedUs(bc->background_timer); + return REDISMODULE_OK; +} + /* Set flags defining capabilities or behavior bit flags. * * REDISMODULE_OPTIONS_HANDLE_IO_ERRORS: @@ -5091,6 +5120,7 @@ RedisModuleBlockedClient *moduleBlockClient(RedisModuleCtx *ctx, RedisModuleCmdF bc->dbid = c->db->id; bc->blocked_on_keys = keys != NULL; bc->unblocked = 0; + bc->background_duration = 0; c->bpop.timeout = timeout; if (islua || ismulti) { @@ -5164,6 +5194,11 @@ int moduleTryServeClientBlockedOnKey(client *c, robj *key) { * * In these cases, a call to RedisModule_BlockClient() will **not** block the * client, but instead produce a specific error reply. + * + * Measuring background time: By default the time spent in the blocked command + * is not account for the total command duration. To include such time you should + * use RM_BlockedClientMeasureTimeStart() and RM_BlockedClientMeasureTimeEnd() one, + * or multiple times within the blocking command background work. */ RedisModuleBlockedClient *RM_BlockClient(RedisModuleCtx *ctx, RedisModuleCmdFunc reply_callback, RedisModuleCmdFunc timeout_callback, void (*free_privdata)(RedisModuleCtx*,void*), long long timeout_ms) { return moduleBlockClient(ctx,reply_callback,timeout_callback,free_privdata,timeout_ms, NULL,0,NULL); @@ -5358,6 +5393,7 @@ void moduleHandleBlockedClients(void) { * was blocked on keys (RM_BlockClientOnKeys()), because we already * called such callback in moduleTryServeClientBlockedOnKey() when * the key was signaled as ready. */ + uint64_t reply_us = 0; if (c && !bc->blocked_on_keys && bc->reply_callback) { RedisModuleCtx ctx = REDISMODULE_CTX_INIT; ctx.flags |= REDISMODULE_CTX_BLOCKED_REPLY; @@ -5366,9 +5402,19 @@ void moduleHandleBlockedClients(void) { ctx.module = bc->module; ctx.client = bc->client; ctx.blocked_client = bc; + monotime replyTimer; + elapsedStart(&replyTimer); bc->reply_callback(&ctx,(void**)c->argv,c->argc); + reply_us = elapsedUs(replyTimer); moduleFreeContext(&ctx); } + /* Update stats now that we've finished the blocking operation. + * This needs to be out of the reply callback above given that a + * module might not define any callback and still do blocking ops. + */ + if (c && !bc->blocked_on_keys) { + updateStatsOnUnblock(c, bc->background_duration, reply_us); + } /* Free privdata if any. */ if (bc->privdata && bc->free_privdata) { @@ -5432,6 +5478,9 @@ void moduleBlockedClientTimedOut(client *c) { ctx.blocked_privdata = bc->privdata; bc->timeout_callback(&ctx,(void**)c->argv,c->argc); moduleFreeContext(&ctx); + if (!bc->blocked_on_keys) { + updateStatsOnUnblock(c, bc->background_duration, 0); + } /* For timeout events, we do not want to call the disconnect callback, * because the blocked client will be automatically disconnected in * this case, and the user can still hook using the timeout callback. */ @@ -9094,6 +9143,8 @@ void moduleRegisterCoreAPI(void) { REGISTER_API(GetBlockedClientPrivateData); REGISTER_API(AbortBlock); REGISTER_API(Milliseconds); + REGISTER_API(BlockedClientMeasureTimeStart); + REGISTER_API(BlockedClientMeasureTimeEnd); REGISTER_API(GetThreadSafeContext); REGISTER_API(GetDetachedThreadSafeContext); REGISTER_API(FreeThreadSafeContext); diff --git a/src/redismodule.h b/src/redismodule.h index 5d46b22f9..9d8c6c5ea 100644 --- a/src/redismodule.h +++ b/src/redismodule.h @@ -776,6 +776,8 @@ REDISMODULE_API int (*RedisModule_IsBlockedTimeoutRequest)(RedisModuleCtx *ctx) REDISMODULE_API void * (*RedisModule_GetBlockedClientPrivateData)(RedisModuleCtx *ctx) REDISMODULE_ATTR; REDISMODULE_API RedisModuleBlockedClient * (*RedisModule_GetBlockedClientHandle)(RedisModuleCtx *ctx) REDISMODULE_ATTR; REDISMODULE_API int (*RedisModule_AbortBlock)(RedisModuleBlockedClient *bc) REDISMODULE_ATTR; +REDISMODULE_API int (*RedisModule_BlockedClientMeasureTimeStart)(RedisModuleBlockedClient *bc) REDISMODULE_ATTR; +REDISMODULE_API int (*RedisModule_BlockedClientMeasureTimeEnd)(RedisModuleBlockedClient *bc) REDISMODULE_ATTR; REDISMODULE_API RedisModuleCtx * (*RedisModule_GetThreadSafeContext)(RedisModuleBlockedClient *bc) REDISMODULE_ATTR; REDISMODULE_API RedisModuleCtx * (*RedisModule_GetDetachedThreadSafeContext)(RedisModuleCtx *ctx) REDISMODULE_ATTR; REDISMODULE_API void (*RedisModule_FreeThreadSafeContext)(RedisModuleCtx *ctx) REDISMODULE_ATTR; @@ -1049,6 +1051,8 @@ static int RedisModule_Init(RedisModuleCtx *ctx, const char *name, int ver, int REDISMODULE_GET_API(GetBlockedClientPrivateData); REDISMODULE_GET_API(GetBlockedClientHandle); REDISMODULE_GET_API(AbortBlock); + REDISMODULE_GET_API(BlockedClientMeasureTimeStart); + REDISMODULE_GET_API(BlockedClientMeasureTimeEnd); REDISMODULE_GET_API(SetDisconnectCallback); REDISMODULE_GET_API(SubscribeToKeyspaceEvents); REDISMODULE_GET_API(NotifyKeyspaceEvent); diff --git a/src/server.c b/src/server.c index 79d6d813d..faaca7215 100644 --- a/src/server.c +++ b/src/server.c @@ -3620,7 +3620,7 @@ void preventCommandReplication(client *c) { */ void call(client *c, int flags) { long long dirty; - ustime_t start, duration; + monotime call_timer; int client_old_flags = c->flags; struct redisCommand *real_cmd = c->cmd; static long long prev_err_count; @@ -3646,9 +3646,10 @@ void call(client *c, int flags) { dirty = server.dirty; prev_err_count = server.stat_total_error_replies; updateCachedTime(0); - start = server.ustime; + elapsedStart(&call_timer); c->cmd->proc(c); - duration = ustime()-start; + const long duration = elapsedUs(call_timer); + c->duration = duration; dirty = server.dirty-dirty; if (dirty < 0) dirty = 0; @@ -3692,7 +3693,10 @@ void call(client *c, int flags) { * arguments. */ robj **argv = c->original_argv ? c->original_argv : c->argv; int argc = c->original_argv ? c->original_argc : c->argc; - slowlogPushEntryIfNeeded(c,argv,argc,duration); + /* If the client is blocked we will handle slowlog when it is unblocked . */ + if (!(c->flags & CLIENT_BLOCKED)) { + slowlogPushEntryIfNeeded(c,argv,argc,duration); + } } freeClientOriginalArgv(c); diff --git a/src/server.h b/src/server.h index 1506c12a8..b293afcee 100644 --- a/src/server.h +++ b/src/server.h @@ -881,6 +881,7 @@ typedef struct client { size_t sentlen; /* Amount of bytes already sent in the current buffer or object being sent. */ time_t ctime; /* Client creation time. */ + long duration; /* Current command duration. Used for measuring latency of blocking/non-blocking cmds */ time_t lastinteraction; /* Time of the last interaction, used for timeout */ time_t obuf_soft_limit_reached_time; uint64_t flags; /* Client flags: CLIENT_* macros. */ @@ -2405,6 +2406,7 @@ void disconnectAllBlockedClients(void); void handleClientsBlockedOnKeys(void); void signalKeyAsReady(redisDb *db, robj *key, int type); void blockForKeys(client *c, int btype, robj **keys, int numkeys, mstime_t timeout, robj *target, struct listPos *listpos, streamID *ids); +void updateStatsOnUnblock(client *c, long blocked_us, long reply_us); /* timeout.c -- Blocked clients timeout and connections timeout. */ void addClientToTimeoutTable(client *c); diff --git a/tests/modules/Makefile b/tests/modules/Makefile index febed82d0..93b4b022f 100644 --- a/tests/modules/Makefile +++ b/tests/modules/Makefile @@ -19,6 +19,7 @@ TEST_MODULES = \ misc.so \ hooks.so \ blockonkeys.so \ + blockonbackground.so \ scan.so \ datatype.so \ auth.so \ diff --git a/tests/modules/blockonbackground.c b/tests/modules/blockonbackground.c new file mode 100644 index 000000000..cf7e9c7c1 --- /dev/null +++ b/tests/modules/blockonbackground.c @@ -0,0 +1,220 @@ +#define REDISMODULE_EXPERIMENTAL_API +#include "redismodule.h" +#include +#include +#include +#include +#include "assert.h" + +#define UNUSED(x) (void)(x) + +/* Reply callback for blocking command BLOCK.DEBUG */ +int HelloBlock_Reply(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + UNUSED(argv); + UNUSED(argc); + int *myint = RedisModule_GetBlockedClientPrivateData(ctx); + return RedisModule_ReplyWithLongLong(ctx,*myint); +} + +/* Timeout callback for blocking command BLOCK.DEBUG */ +int HelloBlock_Timeout(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + UNUSED(argv); + UNUSED(argc); + RedisModuleBlockedClient *bc = RedisModule_GetBlockedClientHandle(ctx); + assert(RedisModule_BlockedClientMeasureTimeEnd(bc)==REDISMODULE_OK); + return RedisModule_ReplyWithSimpleString(ctx,"Request timedout"); +} + +/* Private data freeing callback for BLOCK.DEBUG command. */ +void HelloBlock_FreeData(RedisModuleCtx *ctx, void *privdata) { + UNUSED(ctx); + RedisModule_Free(privdata); +} + +/* The thread entry point that actually executes the blocking part + * of the command BLOCK.DEBUG. */ +void *BlockDebug_ThreadMain(void *arg) { + void **targ = arg; + RedisModuleBlockedClient *bc = targ[0]; + long long delay = (unsigned long)targ[1]; + long long enable_time_track = (unsigned long)targ[2]; + if (enable_time_track) + assert(RedisModule_BlockedClientMeasureTimeStart(bc)==REDISMODULE_OK); + RedisModule_Free(targ); + + struct timespec ts; + ts.tv_sec = delay / 1000; + ts.tv_nsec = (delay % 1000) * 1000000; + nanosleep(&ts, NULL); + int *r = RedisModule_Alloc(sizeof(int)); + *r = rand(); + if (enable_time_track) + assert(RedisModule_BlockedClientMeasureTimeEnd(bc)==REDISMODULE_OK); + RedisModule_UnblockClient(bc,r); + return NULL; +} + +/* The thread entry point that actually executes the blocking part + * of the command BLOCK.DEBUG. */ +void *DoubleBlock_ThreadMain(void *arg) { + void **targ = arg; + RedisModuleBlockedClient *bc = targ[0]; + long long delay = (unsigned long)targ[1]; + assert(RedisModule_BlockedClientMeasureTimeStart(bc)==REDISMODULE_OK); + RedisModule_Free(targ); + struct timespec ts; + ts.tv_sec = delay / 1000; + ts.tv_nsec = (delay % 1000) * 1000000; + nanosleep(&ts, NULL); + int *r = RedisModule_Alloc(sizeof(int)); + *r = rand(); + RedisModule_BlockedClientMeasureTimeEnd(bc); + /* call again RedisModule_BlockedClientMeasureTimeStart() and + * RedisModule_BlockedClientMeasureTimeEnd and ensure that the + * total execution time is 2x the delay. */ + assert(RedisModule_BlockedClientMeasureTimeStart(bc)==REDISMODULE_OK); + nanosleep(&ts, NULL); + RedisModule_BlockedClientMeasureTimeEnd(bc); + + RedisModule_UnblockClient(bc,r); + return NULL; +} + +void HelloBlock_Disconnected(RedisModuleCtx *ctx, RedisModuleBlockedClient *bc) { + RedisModule_Log(ctx,"warning","Blocked client %p disconnected!", + (void*)bc); +} + +/* BLOCK.DEBUG -- Block for milliseconds, then reply with + * a random number. Timeout is the command timeout, so that you can test + * what happens when the delay is greater than the timeout. */ +int HelloBlock_RedisCommand(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + if (argc != 3) return RedisModule_WrongArity(ctx); + long long delay; + long long timeout; + + if (RedisModule_StringToLongLong(argv[1],&delay) != REDISMODULE_OK) { + return RedisModule_ReplyWithError(ctx,"ERR invalid count"); + } + + if (RedisModule_StringToLongLong(argv[2],&timeout) != REDISMODULE_OK) { + return RedisModule_ReplyWithError(ctx,"ERR invalid count"); + } + + pthread_t tid; + RedisModuleBlockedClient *bc = RedisModule_BlockClient(ctx,HelloBlock_Reply,HelloBlock_Timeout,HelloBlock_FreeData,timeout); + + /* Here we set a disconnection handler, however since this module will + * block in sleep() in a thread, there is not much we can do in the + * callback, so this is just to show you the API. */ + RedisModule_SetDisconnectCallback(bc,HelloBlock_Disconnected); + + /* Now that we setup a blocking client, we need to pass the control + * to the thread. However we need to pass arguments to the thread: + * the delay and a reference to the blocked client handle. */ + void **targ = RedisModule_Alloc(sizeof(void*)*3); + targ[0] = bc; + targ[1] = (void*)(unsigned long) delay; + // pass 1 as flag to enable time tracking + targ[2] = (void*)(unsigned long) 1; + + if (pthread_create(&tid,NULL,BlockDebug_ThreadMain,targ) != 0) { + RedisModule_AbortBlock(bc); + return RedisModule_ReplyWithError(ctx,"-ERR Can't start thread"); + } + return REDISMODULE_OK; +} + +/* BLOCK.DEBUG_NOTRACKING -- Block for milliseconds, then reply with + * a random number. Timeout is the command timeout, so that you can test + * what happens when the delay is greater than the timeout. + * this command does not track background time so the background time should no appear in stats*/ +int HelloBlockNoTracking_RedisCommand(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + if (argc != 3) return RedisModule_WrongArity(ctx); + long long delay; + long long timeout; + + if (RedisModule_StringToLongLong(argv[1],&delay) != REDISMODULE_OK) { + return RedisModule_ReplyWithError(ctx,"ERR invalid count"); + } + + if (RedisModule_StringToLongLong(argv[2],&timeout) != REDISMODULE_OK) { + return RedisModule_ReplyWithError(ctx,"ERR invalid count"); + } + + pthread_t tid; + RedisModuleBlockedClient *bc = RedisModule_BlockClient(ctx,HelloBlock_Reply,HelloBlock_Timeout,HelloBlock_FreeData,timeout); + + /* Here we set a disconnection handler, however since this module will + * block in sleep() in a thread, there is not much we can do in the + * callback, so this is just to show you the API. */ + RedisModule_SetDisconnectCallback(bc,HelloBlock_Disconnected); + + /* Now that we setup a blocking client, we need to pass the control + * to the thread. However we need to pass arguments to the thread: + * the delay and a reference to the blocked client handle. */ + void **targ = RedisModule_Alloc(sizeof(void*)*3); + targ[0] = bc; + targ[1] = (void*)(unsigned long) delay; + // pass 0 as flag to enable time tracking + targ[2] = (void*)(unsigned long) 0; + + if (pthread_create(&tid,NULL,BlockDebug_ThreadMain,targ) != 0) { + RedisModule_AbortBlock(bc); + return RedisModule_ReplyWithError(ctx,"-ERR Can't start thread"); + } + return REDISMODULE_OK; +} + +/* BLOCK.DOUBLE_DEBUG -- Block for 2 x milliseconds, + * then reply with a random number. + * This command is used to test multiple calls to RedisModule_BlockedClientMeasureTimeStart() + * and RedisModule_BlockedClientMeasureTimeEnd() within the same execution. */ +int HelloDoubleBlock_RedisCommand(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + if (argc != 2) return RedisModule_WrongArity(ctx); + long long delay; + long long timeout; + + if (RedisModule_StringToLongLong(argv[1],&delay) != REDISMODULE_OK) { + return RedisModule_ReplyWithError(ctx,"ERR invalid count"); + } + + pthread_t tid; + RedisModuleBlockedClient *bc = RedisModule_BlockClient(ctx,HelloBlock_Reply,HelloBlock_Timeout,HelloBlock_FreeData,timeout); + + /* Now that we setup a blocking client, we need to pass the control + * to the thread. However we need to pass arguments to the thread: + * the delay and a reference to the blocked client handle. */ + void **targ = RedisModule_Alloc(sizeof(void*)*2); + targ[0] = bc; + targ[1] = (void*)(unsigned long) delay; + + if (pthread_create(&tid,NULL,DoubleBlock_ThreadMain,targ) != 0) { + RedisModule_AbortBlock(bc); + return RedisModule_ReplyWithError(ctx,"-ERR Can't start thread"); + } + return REDISMODULE_OK; +} + + +int RedisModule_OnLoad(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) { + UNUSED(argv); + UNUSED(argc); + + if (RedisModule_Init(ctx,"block",1,REDISMODULE_APIVER_1) + == REDISMODULE_ERR) return REDISMODULE_ERR; + + if (RedisModule_CreateCommand(ctx,"block.debug", + HelloBlock_RedisCommand,"",0,0,0) == REDISMODULE_ERR) + return REDISMODULE_ERR; + + if (RedisModule_CreateCommand(ctx,"block.double_debug", + HelloDoubleBlock_RedisCommand,"",0,0,0) == REDISMODULE_ERR) + return REDISMODULE_ERR; + + if (RedisModule_CreateCommand(ctx,"block.debug_no_track", + HelloBlockNoTracking_RedisCommand,"",0,0,0) == REDISMODULE_ERR) + return REDISMODULE_ERR; + + return REDISMODULE_OK; +} diff --git a/tests/unit/moduleapi/blockonbackground.tcl b/tests/unit/moduleapi/blockonbackground.tcl new file mode 100644 index 000000000..23111ab73 --- /dev/null +++ b/tests/unit/moduleapi/blockonbackground.tcl @@ -0,0 +1,67 @@ +set testmodule [file normalize tests/modules/blockonbackground.so] + +source tests/support/util.tcl + +start_server {tags {"modules"}} { + r module load $testmodule + + test { blocked clients time tracking - check blocked command that uses RedisModule_BlockedClientMeasureTimeStart() is tracking background time} { + r slowlog reset + r config set slowlog-log-slower-than 200000 + assert_equal [r slowlog len] 0 + r block.debug 0 10000 + assert_equal [r slowlog len] 0 + r config resetstat + r block.debug 200 10000 + assert_equal [r slowlog len] 1 + + set cmdstatline [cmdrstat block.debug r] + + regexp "calls=1,usec=(.*?),usec_per_call=(.*?),rejected_calls=0,failed_calls=0" $cmdstatline usec usec_per_call + assert {$usec >= 100000} + assert {$usec_per_call >= 100000} + } + + test { blocked clients time tracking - check blocked command that uses RedisModule_BlockedClientMeasureTimeStart() is tracking background time even in timeout } { + r slowlog reset + r config set slowlog-log-slower-than 200000 + assert_equal [r slowlog len] 0 + r block.debug 0 20000 + assert_equal [r slowlog len] 0 + r config resetstat + r block.debug 20000 200 + assert_equal [r slowlog len] 1 + + set cmdstatline [cmdrstat block.debug r] + + regexp "calls=1,usec=(.*?),usec_per_call=(.*?),rejected_calls=0,failed_calls=0" $cmdstatline usec usec_per_call + assert {$usec >= 100000} + assert {$usec_per_call >= 100000} + } + + test { blocked clients time tracking - check blocked command with multiple calls RedisModule_BlockedClientMeasureTimeStart() is tracking the total background time } { + r slowlog reset + r config set slowlog-log-slower-than 200000 + assert_equal [r slowlog len] 0 + r block.double_debug 0 + assert_equal [r slowlog len] 0 + r config resetstat + r block.double_debug 100 + assert_equal [r slowlog len] 1 + + set cmdstatline [cmdrstat block.double_debug r] + + regexp "calls=1,usec=(.*?),usec_per_call=(.*?),rejected_calls=0,failed_calls=0" $cmdstatline usec usec_per_call + assert {$usec >= 60000} + assert {$usec_per_call >= 60000} + } + + test { blocked clients time tracking - check blocked command without calling RedisModule_BlockedClientMeasureTimeStart() is not reporting background time } { + r slowlog reset + r config set slowlog-log-slower-than 200000 + assert_equal [r slowlog len] 0 + r block.debug_no_track 200 1000 + # ensure slowlog is still empty + assert_equal [r slowlog len] 0 + } +}