Skip to content

Change active-defrag stats logging#13995

Open
guybe7 wants to merge 5 commits intoredis:unstablefrom
guybe7:defrag_stats
Open

Change active-defrag stats logging#13995
guybe7 wants to merge 5 commits intoredis:unstablefrom
guybe7:defrag_stats

Conversation

@guybe7
Copy link
Copy Markdown
Collaborator

@guybe7 guybe7 commented Apr 30, 2025

During tests, we use loglevel=debug and have small datasets. Under these conditions, we have many very short active defrag cycles (one every 1ms in extreme cases). Every time a defrag cycle starts and ends, it prints some information to the log, which makes the log file very big and the server work much slower.

This commit removes existing logs and adds a log message printed every 1s, summarizing active-defrag's performance in that second that passed.

Other:
Fix run_with_period (used to run every 0.5X instead of every X ms)

During tests we use loglevel=debug and we have small datasets.
Under these conditions, we have a lot of very short active defrag cycles (one every 1ms in extreme cases).
Every time a defrag cycles starts and ends it prints some information to the log, which makes the log file very big and the server to work much slower.

This commit removes exisiting logs and adds a log message that is printed every 1s, summarizing active-defrag's performance in that second that passed.
@guybe7 guybe7 requested a review from sundb April 30, 2025 12:26
@snyk-io
Copy link
Copy Markdown

snyk-io bot commented Apr 30, 2025

🎉 Snyk checks have passed. No issues have been found so far.

security/snyk check is complete. No issues have been found. (View Details)

license/snyk check is complete. No issues have been found. (View Details)

@sundb
Copy link
Copy Markdown
Collaborator

sundb commented Apr 30, 2025

@guybe7 Originally, there were three types of logs: start, end, and mid.
But now we only have one kind of log.
Thus, it becomes difficult to use these logs. When investigating bugs, I often need to know the start and done to determine a complete defragmentation cycle, but now we can't.
I prefer to change the log level from VERBOSE to DEBUG. @oranagra WDYT?

@guybe7
Copy link
Copy Markdown
Collaborator Author

guybe7 commented Apr 30, 2025

@sundb i don't mind changing it to DEBUG

and yes, we lose some debugging visibility in exchange for non-flooded logs (for example, we don't have "start" and "end" logs of active-expiry)

@oranagra
Copy link
Copy Markdown
Member

oranagra commented May 1, 2025

When the db doesn't have a lot of data, and is repeatedly running short defrag cycles, these start and stop prints will flood the log. They must be throttled in some way

@sundb
Copy link
Copy Markdown
Collaborator

sundb commented May 7, 2025

@guybe7 Is the final conclusion as follows now?

  1. Change the loglevel for defrag to DEBUG
  2. Fix incorrect run_with_period()

@guybe7
Copy link
Copy Markdown
Collaborator Author

guybe7 commented May 7, 2025

@sundb yes

@YaacovHazan YaacovHazan moved this from Todo to pending in Redis 8.0 Backport May 26, 2025
sundb added a commit that referenced this pull request May 27, 2025
… timer to run twice as fast (#14081)

This bug was introduced in
[#13814](#13814), and was found by
@guybe7.
It incorrectly moved the update of `server.cronloops` from
`whileBlockedCron()` to `activeDefragTimeProc()`,
causing the cron-based timers to effectively run twice as fast when
active defrag is enabled.
As a result, memory statistics are not updated during blocked
operations.
The repair parts from #13995, because
it needs to be backport, so use a separate pr repair it.
YaacovHazan pushed a commit to YaacovHazan/redis that referenced this pull request May 27, 2025
… timer to run twice as fast (redis#14081)

This bug was introduced in
[redis#13814](redis#13814), and was found by
@guybe7.
It incorrectly moved the update of `server.cronloops` from
`whileBlockedCron()` to `activeDefragTimeProc()`,
causing the cron-based timers to effectively run twice as fast when
active defrag is enabled.
As a result, memory statistics are not updated during blocked
operations.
The repair parts from redis#13995, because
it needs to be backport, so use a separate pr repair it.
YaacovHazan pushed a commit that referenced this pull request May 27, 2025
… timer to run twice as fast (#14081)

This bug was introduced in
[#13814](#13814), and was found by
@guybe7.
It incorrectly moved the update of `server.cronloops` from
`whileBlockedCron()` to `activeDefragTimeProc()`,
causing the cron-based timers to effectively run twice as fast when
active defrag is enabled.
As a result, memory statistics are not updated during blocked
operations.
The repair parts from #13995, because
it needs to be backport, so use a separate pr repair it.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Todo

Development

Successfully merging this pull request may close these issues.

4 participants