Add additional tracing instrumentation.
#97
Conversation
|
Looks pretty good to me |
There was a problem hiding this comment.
at a glance, this seems good to me. one thought i had is that, since mini-redis is intended to be an educational example, it might be good to add some comments actually explaining the use of tracing in this code --- we could add comments summarizing how the instrument macro is being used, and so on?
|
So... LGTM? @jswrenn |
There was a problem hiding this comment.
overall, this looks close. i suggested a few minor changes --- in particular, the ? syntax is being used incorrectly, so we should probably fix that. the rest of my suggestions are not blocking.
it might be interesting to add #[instrument(ret)] and/or #[instrument(err)] in a few places to also emit events with return values? but we can do that in a follow-up branch.
| #[instrument(level = "debug", name = "Handler::process_frame", skip(self))] | ||
| async fn process_frame(&mut self) -> crate::Result<ControlFlow<(), ()>> { |
There was a problem hiding this comment.
it could be interesting to add
| #[instrument(level = "debug", name = "Handler::process_frame", skip(self))] | |
| async fn process_frame(&mut self) -> crate::Result<ControlFlow<(), ()>> { | |
| #[instrument(level = "debug", name = "Handler::process_frame", skip(self), err, ret)] | |
| async fn process_frame(&mut self) -> crate::Result<ControlFlow<(), ()>> { |
to this to also emit events with the return value (and whether it's Ok or Err)?
| async fn process_frame(&mut self) -> crate::Result<ControlFlow<(), ()>> { | ||
| // While reading a request frame, also listen for the shutdown | ||
| // signal. | ||
| let maybe_frame = tokio::select! { |
There was a problem hiding this comment.
i might consider pulling the select! back out into run, and making process_frame be the function that's actually called with the received frame, so we could record the frame as a field on the process_frame span? not a blocker.
This commit lays the ground-work for making mini-redis a better example of an instrumented tokio application. While it does not go so far to turn mini-redis into a fully-featured guide for using `tracing`, it ensures that people who use mini-redis as a basis for experimenting with different subscribers get a more complete experience out-of-the-box.
`str::to_lowercase` had been used for the purposes of case-insensitive
comparisons of command names, but `str::make_ascii_lowercase` is
substantially more performant. Using:
$ redis-benchmark -c 1 -r 128 -t set -n 100000
...with `str::to_lowercase`:
throughput summary: 6651.59 requests per second
latency summary (msec):
avg min p50 p95 p99 max
0.136 0.072 0.135 0.223 0.287 2.807
...with `str::make_ascii_lowercase`:
throughput summary: 9102.49 requests per second
latency summary (msec):
avg min p50 p95 p99 max
0.099 0.064 0.095 0.127 0.191 0.815
While micro-optimizations are usually not appropriate for mini-redis,
this pattern of case-insensitive string comparisons is common, and
using `str::to_lowercase` sets a bad example.
Without these, the flamegraphs produced with tracing-flamegraph look rather sparse for `Command::from_frame`.
This helps draw a distinction between errors caused by bugs in the server, and errors caused by bugs in the client. This latter kind, at least as `Command` parse errors are concerned, is handled now with an `Invalid` pseudo-command (akin to `Unknown`). Drawing this distinction is pedagogically useful, as it helps set up an example usage of `warn!` in `process_frame` (in contrast to other kinds of errors, which are still traced with `error!` in `Listener::run`).
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
|
@hawkw I've applied most of the suggestions (will need to think more about the last two), and rebased (to fix a merge conflict). |
|
too bad this never got merged, it would have been useful |
This commit lays the ground-work for making mini-redis a better example of an instrumented tokio application. While it does not go so far to turn mini-redis into a fully-featured guide for using
tracing, it ensures that people who use mini-redis as a basis for experimenting with different subscribers get a more complete experience out-of-the-box.E.g., with
tracing-treea tracing-tree subscriber andlevel=Debug:INFO mini_redis::server accepting inbound connections ┐mini_redis::db::purge_expired_tasks ├─┐mini_redis::db::Shared::purge_expired_keys ├─┘ ┐mini_redis::server::Handler::run peer_addr=127.0.0.1:56574 ├─┐mini_redis::server::Handler::process_frame │ ├─0ms DEBUG mini_redis::server cmd=Unknown(Unknown { command_name: "config" }) │ ├─0ms DEBUG mini_redis::cmd::unknown response=Error("ERR unknown command 'config'") ├─┘ ├─┐mini_redis::server::Handler::process_frame │ ├─0ms DEBUG mini_redis::server cmd=Unknown(Unknown { command_name: "config" }) │ ├─0ms DEBUG mini_redis::cmd::unknown response=Error("ERR unknown command 'config'") ├─┘ ├─┐mini_redis::server::Handler::process_frame │ ├─0ms WARN mini_redis::connection connection closed abruptly by peer ├─┘ ┘ ┐mini_redis::server::Handler::run peer_addr=127.0.0.1:56576 ├─┐mini_redis::server::Handler::process_frame │ ├─0ms DEBUG mini_redis::server cmd=Set(Set { key: "key:000000000027", value: b"VXK", expire: None }) ├─┘ ├─┐mini_redis::server::Handler::process_frame │ ├─0ms DEBUG mini_redis::server cmd=Set(Set { key: "key:000000000001", value: b"VXK", expire: None }) ├─┘ ├─┐mini_redis::server::Handler::process_frame ├─┘ ┘This PR also reduces
ConnectionReset'errors' to warnings, as they do not reflect errors in mini-redis, but rather client misbehavior. (And you get them frequently when usingredis-benchmark.)