Add INFO stat eviction_exceeded_time by huangzhw · Pull Request #9031 · redis/redis

huangzhw · 2021-06-02T04:19:50Z

Add two INFO metrics:

total_eviction_exceeded_time:69734
current_eviction_exceeded_time:10230

current_eviction_exceeded_time if greater than 0, means how much time current used memory is greater than maxmemory. And we are still over the maxmemory. If used memory is below maxmemory, this metric is reset to 0.
total_eviction_exceeded_time means total time used memory is greater than maxmemory since server startup.
The units of these two metrics are ms.

madolson

I agree this is useful, just some english nitpicks.

src/server.c

src/server.h

madolson · 2021-06-11T04:08:13Z

@redis/core-team Please approve this small new info field.

oranagra · 2021-06-13T07:23:26Z

this metric can indeed shed some light on the matter, but maybe we want to add something even better?
i.e. documenting this metric may be a bit hard (would be coupled with understanding the implementation).
we can (either instead or in addition to) add something that measures the amount of time we were over the memory limit.

e.g. we start some timer as soon as we went over the memory limit (returning EVICT_RUNNING for the first time after a previous EVICT_OK), and then stop measuring when we change the state back to EVICT_OK.
we can show two metrics, one may be the current time since the last EVICT_OK, and one is the accumulated one of all of these since the server started.
such a metric can give the same benefits of the one in this PR, and would be easier to understand and document (it's units are more clear).

WDYT?

huangzhw · 2021-06-13T11:48:08Z

This metric is more clear than count. For count we have to know implementation and maxmemory-eviction-tenacity config.
But there is still problem. With this metric, we can't know how many time we spent on evict.

oranagra · 2021-06-13T12:08:22Z

do we wanna know the total time we spent in eviction? was that the purpose of the current counter?
i'm not sure it's needed, but if we want it, we can add a metric with the total time we spent in eviction (and active expiry too).
i thought the purpose of this metric was to report incomplete eviction (that aborted early despite still being over the limit).

huangzhw · 2021-06-13T12:15:27Z

@oranagra Maybe we won't. After starting eviction, most time are spent.
I still have a problem. performEvictions is called every command. If the QPS is very high (Over 2000), there are many commands at the same event loop. First command takes 0.5ms delay, second command take 1ms and so forth. The comand execute will be very slow.

oranagra · 2021-06-13T15:09:29Z

yes, as long a there's eviction pending, the commands will suffer latency, but that's actually desired in my eyes, it gives some back pressure to the commands to slow them down, otherwise, an aggressive workload will certainly win over eviction.
anyway, let's put aside the actual eviction and discuss the metrics in this PR.

did you intend to measure the relative percentage of the cpu / time spent on eviction? (i.e. the damage it does to commands)
or the effect of the early exit of the eviction on timeout affects the eviction? (i.e. the "damage" the desire for low latency causes to the eviction, preventing it's swift completion)?

if it is the later, then i think the two metrics i suggested are better, if it is the first, we can add a metric for the total time spent in eviction (and maybe active expire), and try to match it against the total cpu time spent in redis, or specifically in commands.

huangzhw · 2021-06-14T01:34:51Z

At first I intend to measure the relative percentage of the cpu / time spent on eviction. But after a second thought, when evicting, Redis uses all of its CPU and time. So this maybe not so useful. This may just tell us whether something slow down the eviction (expire or slow commands).

I think two metrics you suggested are more useful. We can know whether eviction slow down the system and how much time it takes.

madolson · 2021-06-14T03:17:53Z

I agree, I think the time spent is probably better.

running out of time when performEvictions.

This reverts commit 8ed228e.

… times" This reverts commit 688e28f.

sundb · 2021-07-05T00:58:26Z

src/evict.c

+    int result = doPerformEvictions();
+
+    if (result == EVICT_RUNNING) {
+        if (server.stat_last_eviction_exceeded_time == 0) {


Not required under single line {}.

I'm confused whther `{} needed. And space like

f(a,b,c) f(a, b, c) a+b a + b

Some codes have space and some not.

In the old code many of them are without spaces, the back style is basically with spaces, but if you modify the old code, I tend not to change the original style.

sundb · 2021-07-05T01:02:21Z

src/evict.c

+
+    if (result == EVICT_RUNNING) {
+        if (server.stat_last_eviction_exceeded_time == 0) {
+            server.stat_last_eviction_exceeded_time = ustime();


Is it possible to use server.ustime.

I intend to use server.ustime. This function may be called in serverCron, the cached server.ustime may be outdated.

src/evict.c

oranagra · 2021-07-05T11:07:05Z

src/evict.c

+            server.stat_last_eviction_exceeded_time = ustime();
+        }
+    } else if (server.stat_last_eviction_exceeded_time != 0) {
+        server.stat_eviction_exceeded_time += (ustime() - server.stat_last_eviction_exceeded_time);


i think the use of ustime() is actually wrong. we now have a monotonic clock, and that's what we should use to track (and sum) execution time (same as we now do in call for commandstats.

maybe we can also use the monotonic clock for current_eviction_exceeded_time?

src/server.c

src/server.h

src/evict.c

oranagra · 2021-07-06T13:05:31Z

src/evict.c

-        if (server.stat_last_eviction_exceeded_time == 0) {
-            server.stat_last_eviction_exceeded_time = ustime();
-        }
+exceeded_info:


maybe a better name would be update_metrics?

oranagra · 2021-07-06T13:07:18Z

src/server.h

    long long stat_evictedkeys;     /* Number of evicted keys (maxmemory) */
-    long long stat_eviction_exceeded_time;  /* Total time over the memory limit */
-    long long stat_last_eviction_exceeded_time; /* Timestamp of current eviction start */
+    monotime stat_total_eviction_exceeded_time;  /* Total time over the memory limit */


is that really a monotime type? i think just a long long with us units (better mention the units in the comment)

stat_last_eviction_exceeded_time is timestamp, so it is monotime.
stat_total_eviction_exceeded_time can be unsigned long long.

yes, that's what i meant. and if it's just a long long, then we need to document the units.

oranagra · 2021-07-06T13:08:24Z

src/server.c

            server.stat_expire_cycle_time_used/1000,
            server.stat_evictedkeys,
-            server.stat_eviction_exceeded_time + current_eviction_exceeded_time,
+            (unsigned long long) server.stat_total_eviction_exceeded_time + current_eviction_exceeded_time,


i think maybe we better convert both info fields to ms, or even seconds (not very useful in microseconds)

src/evict.c

oranagra

LGTM.
@redis/core-team please approve the new info fields.
@huangzhw thank you! please update the top comment.

src/evict.c

madolson · 2021-07-07T03:37:17Z

Naming looks good to me, I didn't get a chance to look through the code again yet.

itamarhaber

LGTM

madolson · 2021-07-20T05:49:48Z

@huangzhw Want to go ahead and create the doc PR now?

huangzhw · 2021-07-20T11:35:52Z

@madolson OK. I will do it.

current_eviction_exceeded_time. See redis/redis#9031.

huangzhw · 2021-07-27T00:41:09Z

@oranagra As this one was merged, we have metrics in expire and eviction. Do we need samiliar metrics in defrag?

oranagra · 2021-07-27T06:36:51Z

@huangzhw like what? total time we were above the defrag thresholds and active defrag was "active"?
i suppose it can be useful..

huangzhw · 2021-07-27T10:46:09Z

@oranagra Yes. Exactly what I mean. I will try to do it.

…ded_time (redis#9031) Add two INFO metrics: ``` total_eviction_exceeded_time:69734 current_eviction_exceeded_time:10230 ``` `current_eviction_exceeded_time` if greater than 0, means how much time current used memory is greater than `maxmemory`. And we are still over the maxmemory. If used memory is below `maxmemory`, this metric is reset to 0. `total_eviction_exceeded_time` means total time used memory is greater than `maxmemory` since server startup. The units of these two metrics are ms. Co-authored-by: Oran Agra <[email protected]>

Add two INFO metrics: ``` total_active_defrag_time:12345 current_active_defrag_time:456 ``` `current_active_defrag_time` if greater than 0, means how much time has passed since active defrag started running. If active defrag stops, this metric is reset to 0. `total_active_defrag_time` means total time the fragmentation was over the defrag threshold since the server started. This is a followup PR for #9031

enjoy-binbin · 2024-03-05T09:08:08Z

do we want samiliar metrics for activerehashing? i wanted to look for metrics (something like expire_cycle_cpu_milliseconds) to see how much time we generally spend in activerehashing, but i didn’t see it.

oranagra · 2024-03-05T10:14:19Z

i don't these are comparable to the metrics in this PR.
this PR deals with wall-clock duration in which redis was in a certain state.
i.e. how much time passed since it went over the memory limit, or the total time it was in that state.
if we want to measure the CPU effort we invest in expire or rehashing, then that's more in the area of #11963
but anyway, since we do have it for expiry, i suppose we can add it for rehashing.

madolson reviewed Jun 2, 2021

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

src/server.h Outdated Show resolved Hide resolved

madolson previously approved these changes Jun 3, 2021

View reviewed changes

madolson added state:major-decision Requires core team consensus state:needs-doc-pr requires a PR to redis-doc repository labels Jun 3, 2021

huangzhw changed the title ~~Add INFO stat evicted_time_cap_reached_count~~ Add INFO stat eviction_time_limit_exceeded_count Jun 3, 2021

yossigo previously approved these changes Jun 6, 2021

View reviewed changes

madolson added the approval-needed Waiting for core team approval to be merged label Jun 11, 2021

huangzhw marked this pull request as draft July 4, 2021 10:41

huangzhw added 5 commits July 4, 2021 18:44

Add INFO stat evicted_time_cap_reached_count to know how many times

688e28f

running out of time when performEvictions.

fix typo and rename

8ed228e

Revert "fix typo and rename"

c558bff

This reverts commit 8ed228e.

Revert "Add INFO stat evicted_time_cap_reached_count to know how many…

af4d7b2

… times" This reverts commit 688e28f.

add stat_eviction_exceeded_time

d116d61

huangzhw dismissed stale reviews from yossigo and madolson via d116d61 July 4, 2021 10:53

huangzhw force-pushed the evict-reached-info branch from 667c3ec to d116d61 Compare July 4, 2021 10:53

sundb reviewed Jul 5, 2021

View reviewed changes

oranagra reviewed Jul 5, 2021

View reviewed changes

refactor

5415c24

huangzhw commented Jul 6, 2021

View reviewed changes

src/evict.c Show resolved Hide resolved

oranagra reviewed Jul 6, 2021

View reviewed changes

huangzhw changed the title ~~Add INFO stat eviction_time_limit_exceeded_count~~ Add INFO stat eviction_exceeded_time Jul 6, 2021

huangzhw marked this pull request as ready for review July 6, 2021 14:25

oranagra reviewed Jul 6, 2021

View reviewed changes

src/evict.c Outdated Show resolved Hide resolved

src/evict.c Outdated Show resolved Hide resolved

update server.stat_total_eviction_exceeded_time to us

d91f75e

oranagra previously approved these changes Jul 6, 2021

View reviewed changes

oranagra added the release-notes indication that this issue needs to be mentioned in the release notes label Jul 6, 2021

guybe7 reviewed Jul 6, 2021

View reviewed changes

src/evict.c Outdated Show resolved Hide resolved

refactor

8d86ef2

huangzhw dismissed oranagra’s stale review via 8d86ef2 July 7, 2021 00:57

oranagra approved these changes Jul 7, 2021

View reviewed changes

guybe7 approved these changes Jul 7, 2021

View reviewed changes

madolson approved these changes Jul 7, 2021

View reviewed changes

itamarhaber approved these changes Jul 19, 2021

View reviewed changes

madolson removed the approval-needed Waiting for core team approval to be merged label Jul 20, 2021

huangzhw added a commit to huangzhw/redis-doc that referenced this pull request Jul 21, 2021

Add info metrics total_eviction_exceeded_time and

545e4b7

current_eviction_exceeded_time. See redis/redis#9031.

huangzhw mentioned this pull request Jul 21, 2021

Add info metrics about redis#9031 redis/redis-doc#1603

Merged

oranagra merged commit 17511df into redis:unstable Jul 26, 2021

huangzhw deleted the evict-reached-info branch July 27, 2021 00:39

oranagra mentioned this pull request Aug 31, 2021

Add INFO total_active_defrag_time and current_active_defrag_time #9377

Merged

oranagra mentioned this pull request Nov 9, 2022

Client pause write during OOM and pending lazyfree jobs #11193

Closed

Conversation

huangzhw commented Jun 2, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

madolson left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

madolson commented Jun 11, 2021

Uh oh!

oranagra commented Jun 13, 2021

Uh oh!

huangzhw commented Jun 13, 2021

Uh oh!

oranagra commented Jun 13, 2021

Uh oh!

huangzhw commented Jun 13, 2021

Uh oh!

oranagra commented Jun 13, 2021

Uh oh!

huangzhw commented Jun 14, 2021

Uh oh!

madolson commented Jun 14, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

oranagra left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

madolson commented Jul 7, 2021

Uh oh!

itamarhaber left a comment

Choose a reason for hiding this comment

Uh oh!

madolson commented Jul 20, 2021

Uh oh!

huangzhw commented Jul 20, 2021

Uh oh!

huangzhw commented Jul 27, 2021

Uh oh!

oranagra commented Jul 27, 2021

Uh oh!

huangzhw commented Jul 27, 2021

Uh oh!

enjoy-binbin commented Mar 5, 2024

Uh oh!

oranagra commented Mar 5, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

huangzhw commented Jun 2, 2021 •

edited

Loading