Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add asynchronous tracing for Java 8 CompletableFuture in WithSpanAdvice #2530

Merged
merged 23 commits into from
Mar 22, 2021
Merged
Show file tree
Hide file tree
Changes from 16 commits
Commits
Show all changes
23 commits
Select commit Hold shift + click to select a range
fd02a85
Add asynchronous tracing for Java 8 CompletableFuture in Spring WithS…
HaloFour Mar 8, 2021
ee201f3
Add unit tests, fix bugs
HaloFour Mar 8, 2021
6b8f4f1
Placate spotless
HaloFour Mar 8, 2021
7ac98d5
Move MethodSpanStrategies to instrumentation-api, enable registration…
HaloFour Mar 8, 2021
b63a896
Merge branch 'main' of github.com:open-telemetry/opentelemetry-java-i…
HaloFour Mar 8, 2021
44a019a
Switch to withSpan
HaloFour Mar 8, 2021
0f5a370
Fix unit test, refactor MethodSpanStrategy interface
HaloFour Mar 9, 2021
ef099f5
Refactor to instrumentation-api, add docs
HaloFour Mar 9, 2021
b465fbd
spotless, handle null and already done scenarios
HaloFour Mar 9, 2021
7c7d7f1
Minor refactorings, add unit tests
HaloFour Mar 9, 2021
cbe3ec6
Placate checkstyle+spotless
HaloFour Mar 9, 2021
1978160
placate codeNarc
HaloFour Mar 9, 2021
a5b5104
Merge branch 'main' of github.com:open-telemetry/opentelemetry-java-i…
HaloFour Mar 10, 2021
850f3a8
Isolate changes to only otelannotations instrumentation
HaloFour Mar 10, 2021
3c8a635
nix unit tests
HaloFour Mar 10, 2021
b1981de
Consolidate JDK8 strategies, remove use of context
HaloFour Mar 10, 2021
272a0f7
Clarify verbiage in Javadoc
HaloFour Mar 12, 2021
4a717d2
Merge branch 'main' of github.com:open-telemetry/opentelemetry-java-i…
HaloFour Mar 12, 2021
9f74fea
Refactor synchronous completion and add comments, tests
HaloFour Mar 12, 2021
5ad2ea8
Merge branch 'main' of github.com:open-telemetry/opentelemetry-java-i…
HaloFour Mar 16, 2021
16025a4
Early return on uncompleted future
HaloFour Mar 16, 2021
72594ae
Add check to Jdk8MethodStrategy to ensure return type of method is co…
HaloFour Mar 17, 2021
da48a91
A couple of suggestions (#1)
trask Mar 21, 2021
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
import io.opentelemetry.context.Scope;
import java.lang.reflect.Method;
import net.bytebuddy.asm.Advice;
import net.bytebuddy.implementation.bytecode.assign.Assigner;

/**
* Instrumentation for methods annotated with {@link WithSpan} annotation.
Expand Down Expand Up @@ -40,8 +41,10 @@ public static void onEnter(

@Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class)
public static void stopSpan(
@Advice.Origin Method method,
@Advice.Local("otelContext") Context context,
@Advice.Local("otelScope") Scope scope,
@Advice.Return(typing = Assigner.Typing.DYNAMIC) Object returnValue,
@Advice.Thrown Throwable throwable) {
if (scope == null) {
return;
Expand All @@ -51,7 +54,7 @@ public static void stopSpan(
if (throwable != null) {
tracer().endExceptionally(context, throwable);
} else {
tracer().end(context);
tracer().end(context, method, returnValue);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
import io.opentelemetry.api.trace.SpanKind;
import io.opentelemetry.context.Context;
import io.opentelemetry.instrumentation.api.tracer.BaseTracer;
import io.opentelemetry.javaagent.instrumentation.otelannotations.async.MethodSpanStrategies;
import java.lang.reflect.Method;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
Expand All @@ -23,6 +24,8 @@ public static WithSpanTracer tracer() {

private static final Logger log = LoggerFactory.getLogger(WithSpanTracer.class);

private final MethodSpanStrategies methodSpanStrategies = MethodSpanStrategies.getInstance();

public Context startSpan(
Context parentContext, WithSpan applicationAnnotation, Method method, SpanKind kind) {
Span span =
Expand Down Expand Up @@ -69,6 +72,21 @@ public static SpanKind toAgentOrNull(
}
}

/**
* Denotes the end of the invocation of the traced method with a successful result which will end
* the span stored in the passed {@code context}. If the method returned a value representing an
* asynchronous operation then the span will remain open until the asynchronous operation has
HaloFour marked this conversation as resolved.
Show resolved Hide resolved
* completed.
*
* @param result Return value from the traced method.
* @return Either {@code result} or a value composing over {@code result} for notification of
* completion.
*/
public Object end(Context context, Method method, Object result) {
Class<?> returnType = method.getReturnType();
return methodSpanStrategies.resolveStrategy(returnType).end(this, context, returnType, result);
}

@Override
protected String getInstrumentationName() {
return "io.opentelemetry.javaagent.opentelemetry-annotations-1.0";
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,59 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.otelannotations.async;

import io.opentelemetry.context.Context;
import io.opentelemetry.instrumentation.api.tracer.BaseTracer;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.CompletionStage;

enum Jdk8MethodStrategy implements MethodSpanStrategy {
INSTANCE;

@Override
public boolean supports(Class<?> returnType) {
return returnType == CompletionStage.class || returnType == CompletableFuture.class;
}

@Override
public Object end(BaseTracer tracer, Context context, Class<?> returnType, Object result) {
if (result instanceof CompletableFuture) {
trask marked this conversation as resolved.
Show resolved Hide resolved
CompletableFuture<?> future = (CompletableFuture<?>) result;
if (future.isDone()) {
return endSynchronously(future, tracer, context);
}
mateuszrzeszutek marked this conversation as resolved.
Show resolved Hide resolved
return endWhenComplete(future, tracer, context);
} else if (result instanceof CompletionStage) {
trask marked this conversation as resolved.
Show resolved Hide resolved
CompletionStage<?> stage = (CompletionStage<?>) result;
return endWhenComplete(stage, tracer, context);
}
tracer.end(context);
return result;
}

private CompletableFuture<?> endSynchronously(
CompletableFuture<?> future, BaseTracer tracer, Context context) {
try {
future.join();
tracer.end(context);
} catch (Exception exception) {
tracer.endExceptionally(context, exception);
}
return future;
}

private CompletionStage<?> endWhenComplete(
CompletionStage<?> stage, BaseTracer tracer, Context context) {
return stage.whenComplete(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the stage is already complete I think this is guaranteed to be synchronous - I guess we can remove endSynchronously?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I double checked to be sure and yes, whenComplete should always be synchronous, at least given how it's implemented in CompletableFuture<T>. Checking and completing synchronously was more about optimizing away the need for the callback and the extra allocations that requires. It's not observable, but it is cheaper/faster. But if that's not worth the complexity I can remove it.

(result, exception) -> {
if (exception != null) {
tracer.endExceptionally(context, exception);
} else {
tracer.end(context);
}
});
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.otelannotations.async;

import java.util.List;
import java.util.Objects;
import java.util.concurrent.CopyOnWriteArrayList;

/**
* Registry of {@link MethodSpanStrategy} implementations for tracing the asynchronous operations
* represented by the return type of a traced method.
*/
public class MethodSpanStrategies {
private static final MethodSpanStrategies instance = new MethodSpanStrategies();

public static MethodSpanStrategies getInstance() {
return instance;
}

private final List<MethodSpanStrategy> strategies = new CopyOnWriteArrayList<>();

private MethodSpanStrategies() {
strategies.add(Jdk8MethodStrategy.INSTANCE);
}

public void registerStrategy(MethodSpanStrategy strategy) {
Objects.requireNonNull(strategy);
strategies.add(strategy);
}

public MethodSpanStrategy resolveStrategy(Class<?> returnType) {
for (MethodSpanStrategy strategy : strategies) {
if (strategy.supports(returnType)) {
return strategy;
}
}
return MethodSpanStrategy.synchronous();
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.otelannotations.async;

import io.opentelemetry.context.Context;
import io.opentelemetry.instrumentation.api.tracer.BaseTracer;

/**
* Represents an implementation of a strategy for composing over the return value of a traced
* method. If the return value represents the result of an asynchronous operation the implementation
* can compose or register for notification of completion at which point the span representing the
* invocation of the method will be ended.
*/
public interface MethodSpanStrategy {
boolean supports(Class<?> returnType);

/**
* Denotes the end of the invocation of the traced method with a successful result which will end
* the span stored in the passed {@code context}. If the method returned a value representing an
* asynchronous operation then the span will remain open until the asynchronous operation has
* completed.
*
* @param tracer {@link BaseTracer} tracer to be used to end the span stored in the {@code
* context}.
* @param result Return value of the traced method.
* @return Either {@code result} or a value composing over {@code result} for notification of
* completion.
*/
Object end(BaseTracer tracer, Context context, Class<?> returnType, Object result);

/**
* Returns a {@link MethodSpanStrategy} for tracing synchronous methods where the return value
* does not represent the completion of an asynchronous operation.
*/
static MethodSpanStrategy synchronous() {
return SynchronousMethodSpanStrategy.INSTANCE;
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.otelannotations.async;

import io.opentelemetry.context.Context;
import io.opentelemetry.instrumentation.api.tracer.BaseTracer;

enum SynchronousMethodSpanStrategy implements MethodSpanStrategy {
INSTANCE;

@Override
public boolean supports(Class<?> returnType) {
return true;
}

@Override
public Object end(BaseTracer tracer, Context context, Class<?> returnType, Object result) {
tracer.end(context);
return result;
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
/**
* Provides implementations of strategies for tracing methods that return asynchronous and reactive
* values so that the span can be ended when the asynchronous operation completes.
*/
package io.opentelemetry.javaagent.instrumentation.otelannotations.async;
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@
* SPDX-License-Identifier: Apache-2.0
*/

import java.util.concurrent.CompletableFuture

import static io.opentelemetry.api.trace.SpanKind.CLIENT
import static io.opentelemetry.api.trace.SpanKind.PRODUCER
import static io.opentelemetry.api.trace.SpanKind.SERVER
Expand Down Expand Up @@ -144,4 +146,102 @@ class WithSpanInstrumentationTest extends AgentInstrumentationSpecification {
Thread.sleep(500) // sleep a bit just to make sure no span is captured
assertTraces(0) {}
}

def "should capture span for CompletionStage"() {
setup:
def future = new CompletableFuture<String>()
new TracedWithSpan().completionStage(future)

expect:
Thread.sleep(500) // sleep a bit just to make sure no span is captured
assertTraces(0) {}

future.complete("Done")
assertTraces(1) {
trace(0, 1) {
span(0) {
name "TracedWithSpan.completionStage"
kind SpanKind.INTERNAL
hasNoParent()
errored false
attributes {
}
}
}
}
}

def "should capture span for CompletionStage on completed exceptionally"() {
setup:
def future = new CompletableFuture<String>()
new TracedWithSpan().completionStage(future)

expect:
Thread.sleep(500) // sleep a bit just to make sure no span is captured
assertTraces(0) {}

future.completeExceptionally(new IllegalArgumentException("Boom"))
assertTraces(1) {
trace(0, 1) {
span(0) {
name "TracedWithSpan.completionStage"
kind SpanKind.INTERNAL
hasNoParent()
errored true
errorEvent(IllegalArgumentException, "Boom")
attributes {
}
}
}
}
}

def "should capture span for CompletableFuture"() {
setup:
def future = new CompletableFuture<String>()
new TracedWithSpan().completableFuture(future)

expect:
Thread.sleep(500) // sleep a bit just to make sure no span is captured
assertTraces(0) {}

future.complete("Done")
assertTraces(1) {
trace(0, 1) {
span(0) {
name "TracedWithSpan.completableFuture"
kind SpanKind.INTERNAL
hasNoParent()
errored false
attributes {
}
}
}
}
}

def "should capture span for CompletableFuture on completed exceptionally"() {
setup:
def future = new CompletableFuture<String>()
new TracedWithSpan().completableFuture(future)

expect:
Thread.sleep(500) // sleep a bit just to make sure no span is captured
assertTraces(0) {}

future.completeExceptionally(new IllegalArgumentException("Boom"))
assertTraces(1) {
trace(0, 1) {
span(0) {
name "TracedWithSpan.completableFuture"
kind SpanKind.INTERNAL
hasNoParent()
errored true
errorEvent(IllegalArgumentException, "Boom")
attributes {
}
}
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@

import io.opentelemetry.api.trace.SpanKind;
import io.opentelemetry.extension.annotations.WithSpan;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.CompletionStage;

public class TracedWithSpan {

Expand Down Expand Up @@ -54,4 +56,14 @@ public String nestedClients() {
public String innerClient() {
return "hello!";
}

@WithSpan
public CompletionStage<String> completionStage(CompletableFuture<String> future) {
return future;
}

@WithSpan
public CompletableFuture<String> completableFuture(CompletableFuture<String> future) {
return future;
}
}