The problem/use-case that the feature addresses

On our VMs or dockers, some unexpected slowlogs are often observed. In theory, these commands should never appear in the redis, such as incr/decr. We suspect that it is caused by CPU contention, but many of that are difficult to detect confirmed.

Description of the feature 1. before every command is executed, use the getrusage syscall to record the cpu time snapshot, we call it cputime_start 2. After the command is executed, if the execution duration time (wall clock) exceeds the slow check threshold, then we use getrusage to count the cpu time again and subtract it from the cputime_start to get the real cpu overhead 3. recorded cpu overhead in the slowlog

Additional information getrusage is a expensive syscall in linux that may cause redis performance regression. I don't know if there is a cheap interface.

Comment From: oranagra

as you said, calling getrusage per command could be expensive (certainly compared to an INCR), i don't think this is a viable solution. what you can do instead is monitor Redis, feeding the metrics from INFO and other system metrics into Prometheus / Grafana or something like that, then match your slowlog entries to the redis and system metrics and try to conclude what's going on.

p.s. it could be some system related task kicking in to do some house cleaning, or maybe numa_balancing or something alike.

Comment From: judeng

@oranagra thank you for the information you advised. You are right, it is indeed not a viable solution.I got a horrible performance regression about 25% when use pipeline mode. There are some gaps between system monitoring indicators and redis directly. For example, cpu contention is expressed in percentage, while the impact on redis is the latency time unit. In some scenarios, it is difficult to quickly analyze the impact of the system on redis.

Comment From: oranagra

i agree, but i don't see any better way.

Comment From: judeng

it could be some system related task kicking in to do some house cleaning, or maybe numa_balancing or something alike

yes, recently we have observed some numa balancing on physical machines, on 4.18 kernel, when the overall load on physical machines is greater than 25%, numa balance and load balance play like ping-pong, beating redis processes around different numa nodes, which resulted in 1/3 performance degradation of redis, as well as some latency spike. After we turned off numa balance, P99 latency was reduced by 30%, I'm not sure if turning off numa balancing might have side effects, would you like to share your opinion?

Comment From: judeng

Redis [NEW]Record CPU time consumption in slowlog to observe CPU contention Even after we turn off numa balance, load balance is still stealing the cpu time slice of our redis process, usually after do_epoll_wait call, I don’t know how to eliminate and monitor these cpu overhead, hope somebody could give me some advices.

Comment From: oranagra

i suppose it's better to provision each redis process pinned to a certain nume node / core.

Comment From: judeng

@oranagra thank you, binding the socket or core of the CPU is a direct method.While we have almost 100K instances online, and I‘m afraid that binding the CPU may bring management complexity? Regarding turning off numa balancing, would you like to share your views? thank you again

Comment From: oranagra

i don't have anything else to add. of course managing many redis instances of many machines brings complexity. maybe you can think of each NUMA machine as two separate machines, i.e. the same logic you apply to manage redis across machines will apply :shrug: