[improvement] Correctly nest spans when tracing okhttp requests #1069
Conversation
| AsyncTracer tracerTag = chain.request().tag(AsyncTracer.class); | ||
| if (tracerTag == null) { | ||
| AsyncTracerTag tracerTag = chain.request().tag(AsyncTracerTag.class); | ||
| if (tracerTag == null && tracerTag.asyncTracer() == null) { |
There was a problem hiding this comment.
I was surprised errorprone didn't catch this, but then I remembered we don't ahve uber's nullaway enabled!
|
I'm a bit late to this tracing game so I added some comments to try to capture the state of the world. Also here is the 'before this PR' state of the world:
|
| enqueueInternal(callback); | ||
| // tracer.withTrace completes the 'acquire-limiter-enqueue' | ||
| // tracer.withTrace starts the 'acquire-limiter-run' span | ||
| tracer.withTrace(() -> { |
There was a problem hiding this comment.
I think before merging this it would be nice to come up with a solution that doesn't require us to include the acquire-limiter-run and ignore span hacks
There was a problem hiding this comment.
That was my thought as well - this pr is here to point to intended behaviour
There was a problem hiding this comment.
There was a problem hiding this comment.
Why was the hack here needed?
It seems like leaving the old behavior would suffice to leave the acquire-limiter-run span empty and the other spans with the appropriate parents:
tracer.withTrace(() -> null);
enqueueInternal(callback);
There was a problem hiding this comment.
It won't work - the callback is executed on different thread and different trace. You need to add spans to the original trace
|
@iamdanfox in your example, the |
|
This implementation still nests all async spans directly under the caller's span. This makes it difficult to group spans for a request together when multiple requests are being made simultaneously. I've put up an alternative and (IMO) simpler implementation in #1073. In that PR I updated the test before making the change to clearly show the span behavior before and after. I would appreciate if someone could take a look. |
|
Unfortunately the implementations aren't equivalent - this implementation tracks time spent in dispatcher queue while the other doesn't. I am happy to add another top level span but we originally thought it's not helpful, seems we have been wrong. |
robert3005
force-pushed
the
rk/different-spans
branch
from
19d5511 to
ed3f6f3
Compare
|
If you feel this is useful feel free to reopen - it seems that we aren't concerned with this issue right now |
Before this PR
OkHttp: execute-enqueue would measure time in dispatcher pool and acquire-limiter
After this PR
==COMMIT_MSG==
OkHttp tracing spans get correctly nested where acquire-limiter and okhttp: execute don't overlap and okhttp: execute-enqueue measures just the queuing time.
==COMMIT_MSG==
Possible downsides?
Current spans are not easy to understand - this attempts to at least make sure they measure the right thing.