Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 71.53%. Comparing base (3b12132) to head (18a59ae).
⚠️ Report is 26 commits behind head on unstable.

@@             Coverage Diff              @@
##           unstable    #2421      +/-   ##
============================================
+ Coverage     71.51%   71.53%   +0.02%     
============================================
  Files           123      125       +2     
  Lines         67454    69214    +1760     
============================================
+ Hits          48239    49513    +1274     
- Misses        19215    19701     +486     

Do we understand what the rare slow downs are? If it's related to the system (perhaps valkey-server is getting descheduled) then I would expect every test to need this latency increase. If it's specific to just the lists, we probably should investigate that, since it's probably some type of bug.

Let me check other tests too

Fixes #2205?

Do we understand what the rare slow downs are?

According to #2398 (comment) (and a linked Redis issue) it can be related to kernel versions. A kernel mitigation for some CVE. @arkamar might be able to explain more...(?)

According to #2398 (comment) (and a linked Redis issue) it can be related to kernel versions. A kernel mitigation for some CVE. @arkamar might be able to explain more...(?)

I am not sure it's specific to the OS/kernel version because I was able to get above latency on both Ubuntu 20.04 and 24.04

• big hash

[err]: Active Defrag big hash: standalone in tests/unit/memefficiency.tcl
Expected 12 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

[err]: Active Defrag big hash: standalone in tests/unit/memefficiency.tcl
Expected 18 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

• big set

[err]: Active Defrag big set: standalone in tests/unit/memefficiency.tcl
Expected 16 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

Test error (last server port:23623, log:./tests/tmp/server.152762.13/stdout), test will exit now
[err]: Active Defrag big set: standalone in tests/unit/memefficiency.tcl
Expected 12 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)

• big zset

[err]: Active Defrag big zset: standalone in tests/unit/memefficiency.tcl
Expected 24 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

[err]: Active Defrag big zset: standalone in tests/unit/memefficiency.tcl
Expected 16 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

Can we consider increasing the default limit latency to 30 40?

Can we consider increasing the default limit latency to 30?

Yes, good idea.

According to #2398 (comment) (and a linked Redis issue) it can be related to kernel versions. A kernel mitigation for some CVE. @arkamar might be able to explain more...(?)

This doesn't seem related. The original issue that was identified by arkamar is for timeouts, where as this is just taking slightly longer times.

Yes, good idea.

Setting it to 30ms almost defeats the purpose of the latency testing. The goal was to verify that active defragmentation isn't introducing latency spikes, but it seems like it is. Maybe we should allow 1 data point above the threshold?

Maybe we should allow 1 data point above the threshold?

I think that is also good idea but IMO, allowing 1 spike might not generalize across machines, environments, or workloads. Also, future contributors may misunderstand or misuse the logic (e.g., tolerating 1 or 2..), and if a single spike exceeds a drastically high value such as 1 second, it could still be allowed under this rule and go undetected

Maybe instead we could add a debug option to use clock_gettime(CLOCK_PROCESS_CPUTIME_ID) for testing? This should not include time when the process isn't being scheduled, which should hopefully remove some of the edge case times.

We are using the latency data reported by the server via the LATENCY command, which internally measures duration. Based on the implementation (defrag.c#L1165-L1190), I believe this provides sufficiently accurate duration. I also double checked the source of the latency, and it is coming from active-defrag-cycle, not while-blocked-cron

There may be other causes of latency spikes, such as synchronous IO, that also affect these tests? Such as

• [BUG] Synchronous I/O in clusterSaveConfig #2424

There may be other causes of latency spikes, such as synchronous IO, that also affect these tests? Such as

I have a suspicion that it's related to the process being interrupted by the either the guest or host OS. The time will keep ticking up in those cases. We shouldn't be doing any synchronous IO in these tests.

I have a suspicion that it's related to the process being interrupted by the either the guest or host OS.

If this is true, we can't really do much about it, can we? Let's merge this PR for now to unflake the tests?

If this is true, we can't really do much about it, can we? Let's merge this PR for now to unflake the tests?

I suggested we might be able to use the processor clock to actually track time used by the process. If that doesn't work, I think we should remove the latency check and create an issue for later.

I am checking the cpu clock, will get the result soon

I tested with CLOCK_PROCESS_CPUTIME_ID and other options like CLOCK_MONOTONIC, but the latency spikes still appear:

[err]: Active Defrag big hash: standalone in tests/unit/memefficiency.tcl
Expected 21 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)
[err]: Active Defrag big list: standalone in tests/unit/memefficiency.tcl
Expected 8 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)
[err]: Active Defrag big set: standalone in tests/unit/memefficiency.tcl
Expected 10 <= 5 (context: type proc line 18 cmd {assert {$max_latency <= $limit_ms}} proc ::validate_latency level 1)
(Fast fail: test will exit now)

To investigate further, I wrote a simple loop to compare the timing behavior across different clocks, CLOCK_PROCESS_CPUTIME_ID sometimes takes longer than others:

gettimeofday             : 1067362 us
CLOCK_REALTIME           : 1052658 us
CLOCK_MONOTONIC          : 1062182 us
CLOCK_PROCESS_CPUTIME_ID : 1073927 us
CLOCK_THREAD_CPUTIME_ID  : 1057760 us

I found similar issues from online indicating that CLOCK_PROCESS_CPUTIME_ID incurs more overhead, as it queries the scheduler subsystem (via syscall) for fine grained/per thread/process CPU usage. This makes it sometimes more expensive than wall time clocks.

I found similar issues from online indicating that CLOCK_PROCESS_CPUTIME_ID incurs more overhead, as it queries the scheduler subsystem (via syscall) for fine grained/per thread/process CPU usage. This makes it sometimes more expensive than wall time clocks.

What you showed is all less than 1% differences, so I don't think that is causing the spike (the spike is on the order of 10000us) So, it seems like we still aren't sure what is causing the issue :/

I'm OK closing this. I'll make an issue to track it, and then we can merge this. EDIT: new issue #2444