Add config to capture stacktrace when a span duration exceeds threshold
(But only when span is not errored or finished on a different thread.)
Use the following config:
```
Ddd.trace.span.duration.stacktrace.millis=1000
```
(One second is the default, 0 disables.)
MODIFY
dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/asserts/TagsAssert.groovy
dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/asserts/TagsAssert.groovy
@@ -12,6 +12,7 @@ class TagsAssert {
private final BigInteger spanParentId
private final Map<String, Object> tags
private final Set<String> assertedTags = new TreeSet<>()
+ private final Set<String> ignoredTags = ["slow.stack"] // Don't error if this tag isn't checked.
private TagsAssert(DDSpan span) {
this.spanParentId = span.parentId
@@ -102,6 +103,7 @@ class TagsAssert {
void assertTagsAllVerified() {
def set = new TreeMap<>(tags).keySet()
set.removeAll(assertedTags)
+ set.removeAll(ignoredTags)
// The primary goal is to ensure the set is empty.
// tags and assertedTags are included via an "always true" comparison
// so they provide better context in the error message.

MODIFY
dd-trace-api/src/main/java/datadog/trace/api/Config.java
dd-trace-api/src/main/java/datadog/trace/api/Config.java
@@ -23,6 +23,7 @@ import java.util.Properties;
import java.util.Set;
import java.util.SortedSet;
import java.util.UUID;
+import java.util.concurrent.TimeUnit;
import java.util.regex.Pattern;
import lombok.Getter;
import lombok.ToString;
@@ -85,6 +86,8 @@ public class Config {
public static final String SPLIT_BY_TAGS = "trace.split-by-tags";
public static final String SCOPE_DEPTH_LIMIT = "trace.scope.depth.limit";
public static final String PARTIAL_FLUSH_MIN_SPANS = "trace.partial.flush.min.spans";
+ public static final String SPAN_DURATION_STACKTRACE_MILLIS =
+ "trace.span.duration.stacktrace.millis";
public static final String RUNTIME_CONTEXT_FIELD_INJECTION =
"trace.runtime.context.field.injection";
public static final String PROPAGATION_STYLE_EXTRACT = "propagation.style.extract";
@@ -161,6 +164,8 @@ public class Config {
private static final String DEFAULT_SPLIT_BY_TAGS = "";
private static final int DEFAULT_SCOPE_DEPTH_LIMIT = 100;
private static final int DEFAULT_PARTIAL_FLUSH_MIN_SPANS = 1000;
+ private static final int DEFAULT_SPAN_DURATION_STACKTRACE_MILLIS =
+ (int) TimeUnit.SECONDS.toMillis(1);
private static final String DEFAULT_PROPAGATION_STYLE_EXTRACT = PropagationStyle.DATADOG.name();
private static final String DEFAULT_PROPAGATION_STYLE_INJECT = PropagationStyle.DATADOG.name();
private static final boolean DEFAULT_JMX_FETCH_ENABLED = true;
@@ -233,6 +238,7 @@ public class Config {
@Getter private final Set<String> splitByTags;
@Getter private final Integer scopeDepthLimit;
@Getter private final Integer partialFlushMinSpans;
+ @Getter private final long spanDurationStacktraceNanos;
@Getter private final boolean runtimeContextFieldInjection;
@Getter private final Set<PropagationStyle> propagationStylesToExtract;
@Getter private final Set<PropagationStyle> propagationStylesToInject;
@@ -355,6 +361,12 @@ public class Config {
partialFlushMinSpans =
getIntegerSettingFromEnvironment(PARTIAL_FLUSH_MIN_SPANS, DEFAULT_PARTIAL_FLUSH_MIN_SPANS);
+ spanDurationStacktraceNanos =
+ TimeUnit.MILLISECONDS.toNanos(
+ getIntegerSettingFromEnvironment(
+ SPAN_DURATION_STACKTRACE_MILLIS, DEFAULT_SPAN_DURATION_STACKTRACE_MILLIS)
+ .longValue());
+
runtimeContextFieldInjection =
getBooleanSettingFromEnvironment(
RUNTIME_CONTEXT_FIELD_INJECTION, DEFAULT_RUNTIME_CONTEXT_FIELD_INJECTION);
@@ -542,6 +554,14 @@ public class Config {
partialFlushMinSpans =
getPropertyIntegerValue(properties, PARTIAL_FLUSH_MIN_SPANS, parent.partialFlushMinSpans);
+ // do we care about the integer downcast here?
+ spanDurationStacktraceNanos =
+ TimeUnit.MILLISECONDS.toNanos(
+ getPropertyIntegerValue(
+ properties,
+ SPAN_DURATION_STACKTRACE_MILLIS,
+ (int) TimeUnit.NANOSECONDS.toMillis(parent.spanDurationStacktraceNanos)));
+
runtimeContextFieldInjection =
getPropertyBooleanValue(
properties, RUNTIME_CONTEXT_FIELD_INJECTION, parent.runtimeContextFieldInjection);

MODIFY
dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java
dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java
package datadog.opentracing;
+import datadog.trace.api.Config;
import datadog.trace.api.DDTags;
import datadog.trace.api.interceptor.MutableSpan;
import datadog.trace.api.sampling.PrioritySampling;
import datadog.trace.common.util.Clock;
import io.opentracing.Span;
import io.opentracing.tag.Tag;
+import java.io.IOException;
import java.io.PrintWriter;
import java.io.StringWriter;
+import java.io.Writer;
import java.lang.ref.WeakReference;
import java.math.BigInteger;
import java.util.HashMap;
@@ -95,12 +98,112 @@ public class DDSpan implements Span, MutableSpan {
// ensure a min duration of 1
if (this.durationNano.compareAndSet(0, Math.max(1, durationNano))) {
log.debug("Finished: {}", this);
+ addStacktraceIfThresholdExceeded();
context.getTrace().addSpan(this);
} else {
log.debug("{} - already finished!", this);
}
}
+ private void addStacktraceIfThresholdExceeded() {
+ final long spanDurationStacktraceNanos = Config.get().getSpanDurationStacktraceNanos();
+ if (!isError()
+ && spanDurationStacktraceNanos > 0
+ && durationNano.get() > spanDurationStacktraceNanos
+ // If this span was finished async, then the stacktrace will be less meaningful.
+ && context.threadId == Thread.currentThread().getId()) {
+ final Exception stacktrace = new Exception();
+ final Writer stackString = new FilteredStringWriter();
+ stacktrace.printStackTrace(new PrintWriter(stackString));
+ setTag("slow.stack", stackString.toString());
+ }
+ }
+
+ // Writer that skips the first line and lines until FILTER doesn't match.
+ private static final class FilteredStringWriter extends Writer {
+ private static final char[] FILTER = "\tat datadog.opentracing.".toCharArray();
+
+ private final StringWriter writer = new StringWriter();
+
+ private State state = State.SKIP_LINE; // Skip the exception type and message
+ private StringBuilder buffer = new StringBuilder();
+ private int lineIndex = 0;
+
+ @Override
+ public void write(final char[] cbuf, final int off, final int len) throws IOException {
+ if ((off < 0)
+ || (off > cbuf.length)
+ || (len < 0)
+ || ((off + len) > cbuf.length)
+ || ((off + len) < 0)) {
+ throw new IndexOutOfBoundsException();
+ } else if (len == 0) {
+ return;
+ }
+
+ for (int i = off; i < len; i++) {
+ switch (state) {
+ case SKIP_LINE:
+ // Should work fine for windows "\r\n" case too.
+ if (cbuf[i] == '\n') {
+ state = State.READ_LINE;
+ lineIndex = 0;
+ }
+ break;
+
+ case READ_LINE:
+ if (lineIndex == FILTER.length) {
+ state = State.SKIP_LINE;
+ buffer = new StringBuilder();
+ } else if (cbuf[i] == FILTER[lineIndex]) {
+ buffer.append(cbuf[i]);
+ lineIndex++;
+ } else {
+ // writer.write(buffer.toString());
+ // writer.write(cbuf[i]);
+ // buffer = new StringBuilder();
+ // state = State.CONTINUE;
+ state = State.SKIP_NEXT_LINE_THEN_CONTINUE;
+ }
+ continue;
+
+ case SKIP_NEXT_LINE_THEN_CONTINUE:
+ // Should work fine for windows "\r\n" case too.
+ if (cbuf[i] == '\n') {
+ state = State.CONTINUE;
+ }
+ break;
+
+ case CONTINUE:
+ writer.write(cbuf, i, len - (i - off));
+ return;
+ }
+ }
+ }
+
+ @Override
+ public void flush() {
+ writer.flush();
+ }
+
+ @Override
+ public void close() throws IOException {
+ writer.close();
+ }
+
+ @Override
+ public String toString() {
+ return buffer.toString() + writer.toString();
+ }
+
+ private enum State {
+ READ_LINE,
+ SKIP_LINE,
+ SKIP_NEXT_LINE_THEN_CONTINUE,
+ CONTINUE
+ }
+ }
+
@Override
public final void finish() {
if (startTimeNano > 0) {

MODIFY
dd-trace-ot/src/main/java/datadog/opentracing/DDSpanContext.java
dd-trace-ot/src/main/java/datadog/opentracing/DDSpanContext.java
@@ -70,7 +70,8 @@ public class DDSpanContext implements io.opentracing.SpanContext {
// Additional Metadata
private final String threadName = Thread.currentThread().getName();
- private final long threadId = Thread.currentThread().getId();
+ // Visible for use in DDSpan
+ final long threadId = Thread.currentThread().getId();
private final Map<String, String> serviceNameMappings;

MODIFY
dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy
dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanTest.groovy
@@ -3,6 +3,7 @@ package datadog.opentracing
import datadog.opentracing.propagation.ExtractedContext
import datadog.opentracing.propagation.TagContext
+import datadog.trace.api.Config
import datadog.trace.api.sampling.PrioritySampling
import datadog.trace.common.sampling.RateByServiceSampler
import datadog.trace.common.writer.ListWriter
@@ -169,6 +170,22 @@ class DDSpanTest extends DDSpecification {
span.durationNano == 1
}
+ def "stacktrace captured when duration exceeds configured threshold"() {
+ setup:
+ def stackString = new StringWriter()
+ new Exception().printStackTrace(new PrintWriter(stackString))
+ // Get the part of the stack before this test is called.
+ def stack = stackString.toString().split(getClass().getName())[1].split('\n', 2)[1]
+
+ def span = tracer.buildSpan("test").start()
+ span.finish(span.startTimeMicro + TimeUnit.NANOSECONDS.toMicros(Config.get().spanDurationStacktraceNanos) + 1)
+ def actual = span.tags["slow.stack"]
+
+ expect:
+ !actual.toString().isEmpty()
+ actual.endsWith(stack)
+ }
+
def "priority sampling metric set only on root span"() {
setup:
def parent = tracer.buildSpan("testParent").start()

Add config to capture stacktrace when a span duration exceeds threshold

(But only when span is not errored or finished on a different thread.)

Use the following config:
```
-Ddd.trace.span.duration.stacktrace.millis=1000
```
(One second is the default, 0 disables.)