From ee933d9e2b787223effd5afc815897121b1c6575 Mon Sep 17 00:00:00 2001 From: "debing.sun" Date: Sun, 23 Feb 2025 12:58:48 +0800 Subject: [PATCH] Fixed passing incorrect endtime value for module context (#13822) 1) Fix a bug that passing an incorrect endtime to module. This bug was found by @ShooterIT. After #13814, all endtime will be monotonic time, and we should no longer convert it to ustime relative. Add assertions to prevent endtime from being much larger thatn the current time. 2) Fix a race in test `Reduce defrag CPU usage when module data can't be defragged` --------- Co-authored-by: ShooterIT --- src/defrag.c | 5 +++-- src/module.c | 3 +++ tests/modules/defragtest.c | 4 ---- tests/unit/moduleapi/datatype.tcl | 7 +++++-- tests/unit/moduleapi/defrag.tcl | 1 - 5 files changed, 11 insertions(+), 9 deletions(-) diff --git a/src/defrag.c b/src/defrag.c index 3668da2b77..ccf2ebafa1 100644 --- a/src/defrag.c +++ b/src/defrag.c @@ -1007,10 +1007,9 @@ int defragLaterItem(dictEntry *de, unsigned long *cursor, monotime endtime, int } else if (ob->type == OBJ_STREAM) { return scanLaterStreamListpacks(ob, cursor, endtime); } else if (ob->type == OBJ_MODULE) { - long long endtimeWallClock = ustime() + (endtime - getMonotonicUs()); robj keyobj; initStaticStringObject(keyobj, dictGetKey(de)); - return moduleLateDefrag(&keyobj, ob, cursor, endtimeWallClock, dbid); + return moduleLateDefrag(&keyobj, ob, cursor, endtime, dbid); } else { *cursor = 0; /* object type may have changed since we schedule it for later */ } @@ -1227,6 +1226,8 @@ static doneStatus defragModuleGlobals(void *ctx, monotime endtime) { /* Module has been unloaded, nothing to defrag. */ return DEFRAG_DONE; } + /* Interval shouldn't exceed 1 hour */ + serverAssert(!endtime || llabs((long long)endtime - (long long)getMonotonicUs()) < 60*60*1000*1000LL); /* Set up context for the module's defrag callback. */ defrag_module_ctx->module_ctx->endtime = endtime; diff --git a/src/module.c b/src/module.c index 49b2d8d4a6..ee4143869a 100644 --- a/src/module.c +++ b/src/module.c @@ -14009,6 +14009,9 @@ int moduleLateDefrag(robj *key, robj *value, unsigned long *cursor, monotime end moduleValue *mv = value->ptr; moduleType *mt = mv->type; + /* Interval shouldn't exceed 1 hour. */ + serverAssert(!endtime || llabs((long long)endtime - (long long)getMonotonicUs()) < 60*60*1000*1000LL); + RedisModuleDefragCtx defrag_ctx = { endtime, cursor, key, dbid}; /* Invoke callback. Note that the callback may be missing if the key has been diff --git a/tests/modules/defragtest.c b/tests/modules/defragtest.c index 04164c0018..f22414ffdf 100644 --- a/tests/modules/defragtest.c +++ b/tests/modules/defragtest.c @@ -27,7 +27,6 @@ unsigned long int defrag_started = 0; unsigned long int defrag_ended = 0; unsigned long int global_strings_attempts = 0; unsigned long int global_strings_defragged = 0; -unsigned long int global_strings_pauses = 0; unsigned long int global_dicts_resumes = 0; /* Number of dict defragmentation resumed from a previous break */ unsigned long int global_dicts_attempts = 0; /* Number of attempts to defragment dictionary */ unsigned long int global_dicts_defragged = 0; /* Number of dictionaries successfully defragmented */ @@ -65,7 +64,6 @@ static int defragGlobalStrings(RedisModuleDefragCtx *ctx) } if (RedisModule_DefragShouldStop(ctx)) { - global_strings_pauses++; RedisModule_DefragCursorSet(ctx, cursor); return 1; } @@ -216,7 +214,6 @@ static void FragInfo(RedisModuleInfoCtx *ctx, int for_crash_report) { RedisModule_InfoAddFieldLongLong(ctx, "datatype_wrong_cursor", datatype_wrong_cursor); RedisModule_InfoAddFieldLongLong(ctx, "global_strings_attempts", global_strings_attempts); RedisModule_InfoAddFieldLongLong(ctx, "global_strings_defragged", global_strings_defragged); - RedisModule_InfoAddFieldLongLong(ctx, "global_strings_pauses", global_strings_pauses); RedisModule_InfoAddFieldLongLong(ctx, "global_dicts_resumes", global_dicts_resumes); RedisModule_InfoAddFieldLongLong(ctx, "global_dicts_attempts", global_dicts_attempts); RedisModule_InfoAddFieldLongLong(ctx, "global_dicts_defragged", global_dicts_defragged); @@ -249,7 +246,6 @@ static int fragResetStatsCommand(RedisModuleCtx *ctx, RedisModuleString **argv, datatype_wrong_cursor = 0; global_strings_attempts = 0; global_strings_defragged = 0; - global_strings_pauses = 0; global_dicts_resumes = 0; global_dicts_attempts = 0; global_dicts_defragged = 0; diff --git a/tests/unit/moduleapi/datatype.tcl b/tests/unit/moduleapi/datatype.tcl index 7b95680f61..0c2a72b0d6 100644 --- a/tests/unit/moduleapi/datatype.tcl +++ b/tests/unit/moduleapi/datatype.tcl @@ -193,6 +193,7 @@ start_server {tags {"modules"}} { set end_time [expr {[clock seconds] + 10}] set speed_restored 0 while {[clock seconds] < $end_time} { + for {set i 0} {$i < 500} {incr i} { switch [expr {int(rand() * 3)}] { 0 { # Randomly delete a key @@ -213,14 +214,16 @@ start_server {tags {"modules"}} { set random_key "key_[expr {int(rand() * 10000)}]" r datatype.set $random_key 1 $dummy } - } + } ;# end of switch + } ;# end of for # Wait for defragmentation speed to restore. - if {[s active_defrag_running] > 25} { + if {{[count_log_message $loglines "*Starting active defrag, frag=*%, frag_bytes=*, cpu=5?%*"]} > 1} { set speed_restored 1 break; } } + # Make sure the speed is restored assert_equal $speed_restored 1 # After the traffic disappears, the defragmentation speed will decrease again. diff --git a/tests/unit/moduleapi/defrag.tcl b/tests/unit/moduleapi/defrag.tcl index 83595729da..cd9839a403 100644 --- a/tests/unit/moduleapi/defrag.tcl +++ b/tests/unit/moduleapi/defrag.tcl @@ -61,7 +61,6 @@ start_server {tags {"modules"} overrides {{save ""}}} { set info [r info defragtest_stats] assert {[getInfoProperty $info defragtest_global_strings_attempts] > 0} - assert {[getInfoProperty $info defragtest_global_strings_pauses] > 0} assert {[getInfoProperty $info defragtest_global_dicts_attempts] > 0} assert {[getInfoProperty $info defragtest_global_dicts_defragged] > 0} assert_morethan [getInfoProperty $info defragtest_defrag_started] 0