Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

redis.cli: Add --print-duration-threshold option #10055

Open
wants to merge 2 commits into
base: unstable
Choose a base branch
from

Conversation

enjoy-binbin
Copy link
Collaborator

redis-cli in interactive mode will prints the time elapsed of the
operation performed if it took more than 500ms by default.

Added --print-duration-threshold option, now we can set the value
explicitly, the default value is 500 and the unit is milliseconds.

This information is very useful in the interactive mode, which is
different from the slowlog. That we can observe the time consumption
of each command if it touch the threshold.

Note in normal way, the duration is very slow because redis is quite
fast. But it still useful if we encounter network/host issues or some
commands with high time/space complexity.

Some usages:

[root]# ./src/redis-cli --print-duration-threshold 20
127.0.0.1:6379> debug sleep 0.01
OK
127.0.0.1:6379> debug sleep 0.02
OK
(0.02s)

@oranagra
Copy link
Member

oranagra commented Jan 5, 2022

i'm not sure how useful this is.
if you work against a local redis that's not busy, the network overhead and time waiting for execution are small, so indeed you can observe and make use of this output even when the delay is 10 or 20 milliseconds.
but on further away or busier servers, this threshold might be useless, and it starts becoming useful over 1 second.
i.e. to either measure the response time of the server (in case it's busy loading or alike), or a very slow command.

please also note: #9462 that could maybe help solve similar problem (although counted per command, and not per-command execution )

@enjoy-binbin
Copy link
Collaborator Author

yes indeed (also hesitated, some kind a debug action).. The following reply is copied from here: 615ac3d#commitcomment-62543945

just a random idea, we have encountered the problem of high duration (due to cloud service host issue, long time ago).
So I personally hope that this value can be configured to observe the time consumption of the command,
because this information is very useful in the interactive mode, which is different from the slowlog.
of course, in normal way, the duration is very low, observation seems useless ...

image

@oranagra
Copy link
Member

oranagra commented Jan 5, 2022

WOW.. i have a short memory, and i'm also inconsistent with myself 😄.
let's seek a 3rd opinion.
@itamarhaber do you think this is useful enough to justify adding another CLI option?

@oranagra oranagra added this to Needs triage in Triage via automation Jan 5, 2022
@oranagra oranagra moved this from Needs triage to To review in Triage Jan 5, 2022
@enjoy-binbin
Copy link
Collaborator Author

https://pipelines.actions.githubusercontent.com/serviceHosts/c2c792c3-ad47-4cf6-a9bb-d9d840c7c45d/_apis/pipelines/1/runs/6823/signedlogcontent/32?urlExpires=2022-12-14T10%3A24%3A45.0061704Z&urlSigningMethod=HMACV1&urlSignature=I8neWrjZECGgGbzgNPxt%2FkkT4BzBBpSOizpybE7VdUY%3D

2022-12-13T20:36:48.7251010Z !!! WARNING The following tests failed:
2022-12-13T20:36:48.7251210Z 
2022-12-13T20:36:48.7251630Z *** [err]: Interactive CLI: Parsing quotes in tests/integration/redis-cli.tcl
2022-12-13T20:36:48.7252160Z Expected 'Invalid argument(s)' to be equal to '(0.52s)
2022-12-13T20:36:48.7253230Z Invalid argument(s)' (context: type eval line 12 cmd {assert_equal "Invalid argument(s)" [run_command $fd "get \"\"key"]} proc ::test)
2022-12-13T20:36:49.8353150Z Cleanup: may take some time... OK

Recently saw this failure in my daily FreeBSD (due to the assert_equal and duration), and it make me remind this PR.

Expected 'Invalid argument(s)' to be equal to '(0.52s) Invalid argument(s)'

@itamarhaber
Copy link
Member

Yep, seems useful and needed.

redis-cli in interactive mode will prints the time elapsed of the
operation performed if it took more than 500ms by default.

Added `--print-duration-threshold` option, now we can set the value
explicitly, the default value is 500 and the unit is milliseconds.

This information is very useful in the interactive mode, which is
different from the slowlog. That we can observe the time consumption
of each command if it touch the threshold.

Note in normal way, the duration is very slow because redis is quite
fast. But it still useful if we encounter network/host issues or some
commands with high time/space complexity.

Some usages:
```
[root]# ./src/redis-cli --print-duration-threshold 20
127.0.0.1:6379> debug sleep 0.01
OK
127.0.0.1:6379> debug sleep 0.02
OK
(0.02s)
```
@enjoy-binbin enjoy-binbin force-pushed the add_print-duration-threshold_option branch from 7234423 to 9cacd36 Compare December 15, 2022 07:35
@@ -3467,7 +3476,7 @@ static void repl(void) {
}

elapsed = mstime()-start_time;
if (elapsed >= 500 &&
if (elapsed >= config.print_duration_threshold &&
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few thoughts:

  • If we print the duration in seconds (like (0.02s)) the option should also take the value in the same unit, seconds. (We can parse it and store it as milliseconds internally.)
  • The option name is a bit complicated. (I don't have a better idea. The only idea I can come up with now is variants like --print-elapsed-if-gt which is not really better.)
  • Do you really need to tweak the value that much? Perhaps you just want to print the elapsed time for all commands? Maybe we can use the existing --verbose flag, which doesn't do almost anything at all. (All it does it affects some printout in --cluster rebalance.)
Suggested change
if (elapsed >= config.print_duration_threshold &&
if ((elapsed >= 500 || config.verbose) &&

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yean, the name is too long to use.

You are right, actually i want to print the elapsed time for all commands. verbose thing seem fine, not sure which is more versatile though, I actually like the small diff too

Comment on lines +2792 to +2793
if (config.print_duration_threshold < 0) {
fprintf(stderr, "The threshold option must be greater than 0.\n");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

greater than or equal to zero, according to if.

@CLAassistant
Copy link

CLAassistant commented Mar 24, 2024

CLA assistant check
All committers have signed the CLA.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: To review
Triage
To review
Development

Successfully merging this pull request may close these issues.

None yet

5 participants