Set parent spans sensibly when making requests #1073

pkoenig10 · 2019-04-20T03:04:10Z

This is an attempt at a simpler implementation of #1069. I wrote this and then realized the other PR existed. But this is sufficiently different so I figured I'd put it up anyways to get feedback.

Before this PR

All acquire-limiter-* and execute-* spans have the callers span as their parentSpanId. This makes it very difficult to group spans for a request together when multiple requests are being made simultaneously on the same trace. As an example, here is a trace I was viewing recently:

A couple other issues with the current implementation:

The acquire-limiter-run span is useless. It always completes immediately and is just extra noise in the trace logs
Having both enqueue and run spans for both the acquire-limiter and execute is a bit confusing. It is not immediately clear to most users what is meant by "execute" and what tasks are being enqueued and then run.

After this PR

This PR makes a couple changes:

Create a top-level enqueue span around submitting the request. This is useful to provide a single span under which all request spans will exist. This is the only span whose parent is the caller's span.
Remove the execute-* async span and instead nest the enqueueing of the request in the limiter-run span. This make the limiter-run span no longer useless since it contains the actual request.

The first commit in this PR just updates the tracing test to clearly show how spans are parented. This should make it easier to understand the behavior changes as a result of this change.

Possible downsides?

The top-level enqueue span will be very short and will not outlive the request. Making this span live as long as the request is a bit error-prone since the span would have to be started, left open, and then completed on another thread. Getting the spans to work out in this way is tricky.

pkoenig10 · 2019-04-20T05:19:09Z

conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java

+
+        assertThat(spans).containsExactly(
+                span(spans.get(0), traceId, spanIds.get(2), SpanType.LOCAL, "OkHttp: limiter-enqueue"),
+                span(spans.get(1), traceId, spanIds.get(2), SpanType.LOCAL, "OkHttp: limiter-run"),


We could also just remove this span entirely and have the dispatcher span be directly under the enqueue span. This would require adding a method to the AsyncTracer that only completes the async span:

public void completeSpan() { Trace originalTrace = Tracer.getAndClearTrace(); Tracer.setTrace(deferredTrace); // Finish the enqueue span Tracer.fastCompleteSpan(); Tracer.setTrace(originalTrace); }

Alternatively we could modify the AsyncTracer to allow for different operation names for the "execute" and "run" spans to improve the naming (something like "limiter" and "execute").

I'd prefer to remove/deprecate AsyncTracer in favor of proper APIs to support what we want to measure. palantir/tracing-java#124

diogoholanda · 2019-04-22T14:12:04Z

conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java

+                span(spans.get(1), traceId, spanIds.get(2), SpanType.LOCAL, "OkHttp: limiter-run"),
+                span(spans.get(2), traceId, parentSpanId, SpanType.LOCAL, "OkHttp: enqueue"),
+                span(spans.get(3), traceId, spanIds.get(4), SpanType.CLIENT_OUTGOING, "OkHttp: GET /{param}"),
+                span(spans.get(4), traceId, spanIds.get(1), SpanType.LOCAL, "OkHttp: dispatcher"));


It seems weird to me that this span is parented by the useless OkHttp: limiter-run. In my opinion, OkHttp: limiter-run shouldn't even exist. If it does in the meantime, it shouldn't be the parent span of anything.
I also like the approach on #1069 of just removing the Dispatcher span altogether and going straight to the CLIENT_OUTGOING span, which should be a sibling of the OkHttp: limiter-* spans

In my opinion, OkHttp: limiter-run shouldn't even exist

I agree. Ideally there would just be a single span to track the time spent waiting for the limiter. But doing so requires a change to `AsyncTracer. See my comment at #1073 (comment).

I also like the approach on #1069 of just removing the Dispatcher span altogether

I don't disagree, but there needs to be some mechanism to carry the trace over to the dispatcher thread. This should probably happen before anything runs (ie not in an interceptor). I don't think it unreasonable to keep the dispatcher span since

We instrument all other executors in this same way

There is value in tracking the duration of tasks running in this executor. This helps us know if we are spending a lot of time in a dispatcher thread doing work outside the request span.

My first point is that the second best thing for OkHttp: limiter-run not existing is OkHttp: limiter-run being a no-op and having no children. We can always remove it later once we fix AsyncTrancer.

diogoholanda · 2019-04-22T14:13:56Z

okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java

        ListenableFuture<Limiter.Listener> limiterListener = limiter.acquire();
        request().tag(ConcurrencyLimiterListener.class).setLimiterListener(limiterListener);
        Futures.addCallback(limiterListener, new FutureCallback<Limiter.Listener>() {
            @Override
            public void onSuccess(Limiter.Listener listener) {
-                tracer.withTrace(() -> null);
-                enqueueInternal(callback);
+                tracer.withTrace(() -> {


I think you shouldn't make this change (given my comment above on the test)

diogoholanda · 2019-04-22T14:22:18Z

okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java

@@ -155,14 +156,22 @@ private static ResponseBody buffer(MediaType mediaType, byte[] bodyBytes) {

    @Override
    public void enqueue(Callback callback) {
-        AsyncTracer tracer = new AsyncTracer("OkHttp: acquire-limiter");
+        try (CloseableTracer ignored = CloseableTracer.startSpan("OkHttp: enqueue")) {


Won't this lead to a very fast span (just enqueing) which is the parent of much longer spans (the actual call)? Ideally, the duration of a span would contain all its children. I would suggest either removing this, or having a span that actually lasts for the whole duration of the request (which I believe is something that #1069 does and was one of my original reasons to start discussing that change with @robert3005)

Ideally, the duration of a span would contain all its children

Ideally yes, but the more I think about it, the less important I think this is. Ideally a span's end time should:

Be after the end time of it's last child

Be before the start time of it's next sibling

However with async tasks, we can only pick one of these. I would argue that sibling spans occuring at the same time on the same trace is even more confusing than a parent that does not outlive it's child. Especially since that is exactly what is happening when work is done asynchronously - the parent finished submitting work before the work is done.

I would suggest either removing this

We need something here under which all other request spans can exist. Otherwise all these spans are parented by the caller's span which leads to the confusion I detail in the PR description.

The reason I think it is important is because if a span has a very small duration, I assume I don't need to expand it to check its children. It seems like a fair assumption to make, otherwise I would always have to expand all spans, no matter how long they are. I actually feel somewhat strongly about trying to keep a span's duration expanding through all its children duration.

If you have reasons not to remove this span, could you make it cover the whole request, from limiter to the actual response coming back.

I don't disagree with you. This is actually the behavior I wanted when I started to make this changes. But doing this with the current API is very error-prone since it requires:

Calling startSpan at the beginning of the request

Then not closing the span in order to keep in on the stack (this is different than the behavior of AsyncTracer, which immediately discards this span)

Calling fastCompleteSpan after the request is done, assuming that the span on the top of the stack is the one we started in step (1).

There are a couple things we can do to mitigate this:

Design a better API to to safely support these types of spans (I think that's what Support for tracing asynchronous operations tracing-java#124 is attempting to do)

Design a better API that verifies the span on the top of the stack is an expected span when closing

Doing this actually requires removing the dispatcher span, otherwise (3) will never be true since the dispatcher span will always be on the top of the stack. But then you need another mechanism to transfer the trace from the submitting thread to the dispatcher thread. And preferably one that captures as much of the dispatcher work as possible (ideally, you would capture all of it, which is what the wrapped executor does).

This actually doesn't work. Since palantir/tracing-java#97, DeferredTracer no longer keeps the span stack of the caller but only keeps the parentSpanId.

Design a better API to to safely support these types of spans (I think that's what palantir/tracing-java#124 is attempting to do)

That's correct

Design a better API that verifies the span on the top of the stack is an expected span when closing

Tracking here: palantir/tracing-java#34

iamdanfox · 2019-09-11T20:02:48Z

Closing out because I hope 4.36.0 will satisfy the outcome: https://github.com/palantir/conjure-java-runtime/releases/tag/4.36.0

pkoenig10 requested a review from a team as a code owner April 20, 2019 03:04

pkoenig10 mentioned this pull request Apr 20, 2019

[improvement] Correctly nest spans when tracing okhttp requests #1069

Closed

pkoenig10 commented Apr 20, 2019

View reviewed changes

diogoholanda reviewed Apr 22, 2019

View reviewed changes

pkoenig10 added 3 commits May 31, 2019 10:42

Check parentSpanId in tests

51f9648

Set parent spans sensibly when making requests

f664907

Don't nest request under limiter-run span

913a102

robert3005 mentioned this pull request Jun 5, 2019

Sensibly nest spans in RemotingOkHttpCall #1121

Closed

iamdanfox closed this Sep 11, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Set parent spans sensibly when making requests #1073

Set parent spans sensibly when making requests #1073

pkoenig10 commented Apr 20, 2019 •

edited

Loading

pkoenig10 Apr 20, 2019 •

edited

Loading

pkoenig10 Apr 21, 2019 •

edited

Loading

carterkozak Apr 21, 2019

diogoholanda Apr 22, 2019 •

edited

Loading

pkoenig10 Apr 22, 2019 •

edited

Loading

diogoholanda Apr 22, 2019

diogoholanda Apr 22, 2019

diogoholanda Apr 22, 2019

pkoenig10 Apr 22, 2019 •

edited

Loading

diogoholanda Apr 22, 2019

pkoenig10 Apr 22, 2019

pkoenig10 Apr 22, 2019 •

edited

Loading

carterkozak Apr 22, 2019

iamdanfox commented Sep 11, 2019

Set parent spans sensibly when making requests #1073

Set parent spans sensibly when making requests #1073

Conversation

pkoenig10 commented Apr 20, 2019 • edited Loading

Before this PR

After this PR

Possible downsides?

pkoenig10 Apr 20, 2019 • edited Loading

Choose a reason for hiding this comment

pkoenig10 Apr 21, 2019 • edited Loading

Choose a reason for hiding this comment

carterkozak Apr 21, 2019

Choose a reason for hiding this comment

diogoholanda Apr 22, 2019 • edited Loading

Choose a reason for hiding this comment

pkoenig10 Apr 22, 2019 • edited Loading

Choose a reason for hiding this comment

diogoholanda Apr 22, 2019

Choose a reason for hiding this comment

diogoholanda Apr 22, 2019

Choose a reason for hiding this comment

diogoholanda Apr 22, 2019

Choose a reason for hiding this comment

pkoenig10 Apr 22, 2019 • edited Loading

Choose a reason for hiding this comment

diogoholanda Apr 22, 2019

Choose a reason for hiding this comment

pkoenig10 Apr 22, 2019

Choose a reason for hiding this comment

pkoenig10 Apr 22, 2019 • edited Loading

Choose a reason for hiding this comment

carterkozak Apr 22, 2019

Choose a reason for hiding this comment

iamdanfox commented Sep 11, 2019

pkoenig10 commented Apr 20, 2019 •

edited

Loading

pkoenig10 Apr 20, 2019 •

edited

Loading

pkoenig10 Apr 21, 2019 •

edited

Loading

diogoholanda Apr 22, 2019 •

edited

Loading

pkoenig10 Apr 22, 2019 •

edited

Loading

pkoenig10 Apr 22, 2019 •

edited

Loading

pkoenig10 Apr 22, 2019 •

edited

Loading