Uh oh!
There was an error while loading. Please reload this page.
Implement HttpTelemetry for HTTP/3 - #65644
Conversation
This comment was marked as resolved.
This comment was marked as resolved.
ghost
commented
Feb 21, 2022
Tagging subscribers to this area: @dotnet/ncl |
This comment was marked as resolved.
This comment was marked as resolved.
MihaZupan
commented
Feb 21, 2022
/azp run runtime-libraries-coreclr outerloop |
|
Azure Pipelines successfully started running 1 pipeline(s). |
| { | ||
| if (HttpTelemetry.Log.IsEnabled() && queueDuration.IsActive) | ||
| { | ||
| HttpTelemetry.Log.Http30RequestLeftQueue(queueDuration.GetElapsedTime().TotalMilliseconds); |
There was a problem hiding this comment.
In case the connection gets closed in the meantime, the request will get retried on a different connection (line 224). I'm not sure what counts into the "waiting time in the queue" in such case, but this will report as request left the queue.
There was a problem hiding this comment.
This should be rare-ish to happen, but yes, you may see multiple RequestLeftQueue events for a given request.
Similarly with 1.1, there is a race where we would retry if the server disconnects here, logging RequestLeftQueue twice.
Similarly with resets on HTTP/2, we may re-insert the request to the queue.
I'm not sure we can/should improve that somehow. I feel it's still valuable to include the time on queue here even if the request will just end up back in the queue.
There was a problem hiding this comment.
If we do similar thing with H/1.1 and H/2 then this is fine. I'm mostly trying to make sure we keep similar behavior between the protocols so that one counter doesn't mean something else based on HTTP version.
| { | ||
| _stream.AbortWrite((long)Http3ErrorCode.RequestCancelled); | ||
| throw new OperationCanceledException(ex.Message, ex, cancellationToken); | ||
| throw new TaskCanceledException(ex.Message, ex, cancellationToken); |
There was a problem hiding this comment.
Why this change? Is it to unify exception types with H/2, H/1.1?
There was a problem hiding this comment.
Right, this is something that both 1.1 and 2 seem to be doing.
E.g. for 1.1:
It seems harmless enough of a change (given TCE derives from OCE), or we could update the failure tests to expect OCE instead.
Uh oh!
There was an error while loading. Please reload this page.
| _headerState = HeaderState.TrailingHeaders; | ||
| if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); |
There was a problem hiding this comment.
This is not exactly the moment when the headers get sent, but it gets muddy with the gathered buffer with content. How does this compare with H/2 and H/1.1? Is is worth trying to refine the moment or not?
There was a problem hiding this comment.
On HTTP/2, we will actually include the time to write out the headers on the wire (code). That is because the time when the headers are sent is well-defined since we immediately serialize the action on the multiplexed connection.
On HTTP/1.1 and 3, however, the headers may not end up being sent right away, but only with the first flush of the request content, which may be under user's control.
We could report a more accurate timestamp of when the headers are actually sent, but these events being Start/Stop complicates the matter. If ThreadPool activity tracking is on, I don't see how we would get the async scope for Start/Stop to match, given Stop would result as part of the content copying outside of SendAsync.
There was a problem hiding this comment.
I guess this is good enough and not worth the trouble. Especially, if we're already not pedantic about the exact times in H/1.1
Fixes#40896