feat: add debug spans for decoding requests - #1760
Conversation
| if !self.buf.has_remaining() { | ||
| return Ok(None); | ||
| } | ||
|
|
||
| let span = span.get_or_insert_with(|| { | ||
| tracing::debug_span!( | ||
| "read_header", | ||
| compression = tracing::field::Empty, | ||
| body.bytes = tracing::field::Empty, | ||
| ) | ||
| }); |
There was a problem hiding this comment.
This avoids creating a vestigial read_header span for unary endpoints, which have only a single message. This does mean that there may be a small gap if there isn't any pending header data for a streaming endpoint until the first bytes of the next header are available in the buffer.
| len: usize, | ||
| }, | ||
| Error(Status), | ||
| Error(Box<Status>), |
There was a problem hiding this comment.
Boxing here significantly reduces the size of State and StreamingInner as a result, even with the addition of tracing::Span to the other variants.
3ac6746 to
1aa0321
Compare
|
I wonder if there's value in more explicit boxing of |
c1963b5 to
971d51f
Compare
| ) -> Result<Option<DecodeBuf<'_>>, Status> { | ||
| if let State::ReadHeader = self.state { | ||
| if let State::ReadHeader { span } = &mut self.state { | ||
| if !self.buf.has_remaining() { |
There was a problem hiding this comment.
Why add this guard here? Can we just do the self.buf.remaining() < HEADER_SIZE check here instead?
There was a problem hiding this comment.
I had considered that. The reason for the guard at all is that, even with unary requests, Tonic still polls the stream after reading the first message. That was generating read_header, read_body, read_header for these unary requests, with the last read_header really being vestigial, since the stream would then be dropped after the message. I opted to try to remove this vestigial span, but we could simplify by re-introducing it.
With that in mind, if there are still bytes in the stream, then that would indicate that there's a header already partially in the input, so opening a new span is indicated. If not, then we'd delay opening a new span (but that also means that a new span wouldn't capture the time from the empty poll until the next header started appearing in the buffer).
Changing it so that the span is only opened once 5 bytes are in the buffer would mean that the span would only open once we've already completely read the header, making this really just timing the extraction of the u8 compression encoding and u32 payload size, which probably then isn't all that valuable.
Another option here is to have a debug span one level higher for the entire stream itself, skip the span for the header, and keep a span for the body.
|
This seems reasonable to me, thanks! (Sorry for the delay in reviewing.)
Could make sense to evaluate this next, in a separate PR? How/why is the size of |
marcus-griep-simplisafe
left a comment
marcus-griep-simplisafe
left a comment
There was a problem hiding this comment.
Could make sense to evaluate this next, in a separate PR? How/why is the size of
Statuscausing issues for you?
I'm not opposed to taking this out. There's probably not a lot of issue here, other than the fact that it now requires more data move instructions to copy up the Result on every return. Since this is in the hot-path for deserialization, and Status in this case is an error condition, optimizing the size of the non-error case seemed appropriate, but I don't have any data that indicates it is required.
|
@neoeinstein or someone else would like to step up and finish this PR? We already have the status stuff merged or about to be merged so we just need the span stuff. |
LucioFranco
added
the
E-help-wanted
Adds tracing debug spans to the streaming decoder to measure latency and track payload metrics (compression type, compressed bytes, and uncompressed bytes) during message decoding. Co-authored-by: Marcus Griep <marcus@griep.us>
198de46 to
67a7199
Compare
|
I've pushed a merge of the master branch changes since this was opened, and I think also addressed the requested items from the PR here. @LucioFranco do you mind doing a quick review? (Just moving through the backlog looking for likely things to clean up and close out.) |
5 participants
Closes: #1759
Motivation
Adds optional debug spans into the decoder state. At the same time, it resolves a size regression in the
Statestruct, which got much larger because of the inclusion of theStatusin the error. The size change overall is from 16 bytes (v0.11.0) to 176 (master) to 56 (this PR).Solution
Adds tracing spans at the debug level for tracking decoding of streaming messages. This should have negligible overhead when debug spans are not enabled, and provide some more context when they are enabled.
Boxes the
Statusin theErrorvariant to avoid size bloat for the common case.If desired, this functionality could be gated behind a feature, but I start off by avoiding the extra complexity of adding conditional compilation code.