From 0068255a4aa47ffd42ae1b804b26fd8a50d98901 Mon Sep 17 00:00:00 2001 From: Sylvain Juge <763082+SylvainJuge@users.noreply.github.com> Date: Thu, 21 Dec 2023 11:59:20 +0100 Subject: [PATCH 1/4] stacktrace capture when span ends --- .../co/elastic/apm/agent/impl/ElasticApmTracer.java | 8 -------- .../co/elastic/apm/agent/impl/transaction/Span.java | 11 +++++++++++ 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java index a77c4e5f49..25e26f2bf4 100644 --- a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java +++ b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java @@ -107,7 +107,6 @@ public class ElasticApmTracer implements Tracer { private static volatile boolean classloaderCheckOk = false; private final ConfigurationRegistry configurationRegistry; - private final StacktraceConfiguration stacktraceConfiguration; private final ApmServerClient apmServerClient; private final List lifecycleListeners = new CopyOnWriteArrayList<>(); private final ObjectPool transactionPool; @@ -203,7 +202,6 @@ private static void checkClassloader() { this.metricRegistry = metricRegistry; this.configurationRegistry = configurationRegistry; this.reporter = reporter; - this.stacktraceConfiguration = configurationRegistry.getConfig(StacktraceConfiguration.class); this.apmServerClient = apmServerClient; this.ephemeralId = ephemeralId; this.metaDataFuture = metaDataFuture; @@ -574,12 +572,6 @@ private void reportSpan(Span span) { // makes sure that parents are also non-discardable span.setNonDiscardable(); - long spanStackTraceMinDurationMs = stacktraceConfiguration.getSpanStackTraceMinDurationMs(); - if (spanStackTraceMinDurationMs >= 0 && span.isSampled() && span.getStackFrames() == null) { - if (span.getDurationMs() >= spanStackTraceMinDurationMs) { - span.withStacktrace(new Throwable()); - } - } reporter.report(span); } diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java index 7b214ddbd8..c4183d2cff 100644 --- a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java +++ b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java @@ -26,6 +26,7 @@ import co.elastic.apm.agent.impl.context.ServiceTarget; import co.elastic.apm.agent.impl.context.SpanContext; import co.elastic.apm.agent.impl.context.Url; +import co.elastic.apm.agent.impl.stacktrace.StacktraceConfiguration; import co.elastic.apm.agent.tracer.util.ResultUtil; import co.elastic.apm.agent.sdk.logging.Logger; import co.elastic.apm.agent.sdk.logging.LoggerFactory; @@ -43,6 +44,7 @@ public class Span extends AbstractSpan implements Recyclable, co.elastic.a private static final Logger logger = LoggerFactory.getLogger(Span.class); public static final long MAX_LOG_INTERVAL_MICRO_SECS = TimeUnit.MINUTES.toMicros(5); private static long lastSpanMaxWarningTimestamp; + private final StacktraceConfiguration stacktraceConfiguration; /** * A subtype describing this span (eg 'mysql', 'elasticsearch', 'jsf' etc) @@ -86,6 +88,7 @@ public void setNonDiscardable() { public Span(ElasticApmTracer tracer) { super(tracer); + this.stacktraceConfiguration = tracer.getConfig(StacktraceConfiguration.class); } public Span start(TraceContext.ChildContextCreator childContextCreator, T parentContext, Baggage parentBaggage, long epochMicros) { @@ -263,6 +266,14 @@ public void beforeEnd(long epochMicros) { @Override protected void afterEnd() { + // capture stack trace when the span ends, relies on this method being called synchronously from the instrumentation + long spanStackTraceMinDurationMs = stacktraceConfiguration.getSpanStackTraceMinDurationMs(); + if (spanStackTraceMinDurationMs >= 0 && isSampled() && stackFrames == null) { + if (getDurationMs() >= spanStackTraceMinDurationMs) { + this.stacktrace = new Throwable(); + } + } + // Why do we increment references of this span here? // The only thing preventing the "this"-span from being recycled is the initial reference increment in onAfterStart() // There are multiple ways in afterEnd() on how this reference may be decremented and therefore potentially causing recycling: From 91f057d1e82242f02095f0f719822bcc0546f245 Mon Sep 17 00:00:00 2001 From: Sylvain Juge <763082+SylvainJuge@users.noreply.github.com> Date: Thu, 21 Dec 2023 13:57:04 +0100 Subject: [PATCH 2/4] assert stack trace content --- .../apm/agent/impl/ElasticApmTracerTest.java | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java index a5ff19054e..57dce88032 100644 --- a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java +++ b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java @@ -159,11 +159,20 @@ void testEnableStacktraces() throws InterruptedException { Span span = tracerImpl.getActive().createSpan(); try (Scope spanScope = span.activateInScope()) { Thread.sleep(10); - span.end(); + stackTraceEndSpan(span); } transaction.end(); } - assertThat(reporter.getFirstSpan().getStacktrace()).isNotNull(); + Throwable stackTrace = reporter.getFirstSpan().getStacktrace(); + assertThat(stackTrace).isNotNull(); + assertThat(Arrays.stream(stackTrace.getStackTrace()).filter(stackTraceElement -> + stackTraceElement.getMethodName().equals("stackTraceEndSpan") + && stackTraceElement.getClassName().equals(ElasticApmTracerTest.class.getName()))).hasSize(1); + } + + private static void stackTraceEndSpan(Span span) { + // dummy method used just to verify that the captured stack trace contains it + span.end(); } @Test From 5eabcaeb940faa5ac98c8d8213deaadd83a7c26c Mon Sep 17 00:00:00 2001 From: Sylvain Juge <763082+SylvainJuge@users.noreply.github.com> Date: Thu, 21 Dec 2023 13:59:02 +0100 Subject: [PATCH 3/4] update changelog --- CHANGELOG.asciidoc | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index a0c8f7563f..f271898cde 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -31,6 +31,10 @@ Use subheadings with the "=====" level for adding notes for unreleased changes: === Unreleased +[float] +===== Bug fixes +* Fix span stack trace when combined with span compression - {pull}3474[#3474] + [[release-notes-1.x]] === Java Agent version 1.x From 8d43455233ea87fbdf3b545d3a0dd3e73aa25560 Mon Sep 17 00:00:00 2001 From: Sylvain Juge <763082+SylvainJuge@users.noreply.github.com> Date: Thu, 21 Dec 2023 14:07:55 +0100 Subject: [PATCH 4/4] fix pebkc compile error --- .../java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java | 1 + 1 file changed, 1 insertion(+) diff --git a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java index 57dce88032..b2771cfd8a 100644 --- a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java +++ b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java @@ -48,6 +48,7 @@ import javax.annotation.Nullable; import java.io.IOException; import java.util.HashMap; +import java.util.Arrays; import java.util.List; import java.util.Map; import java.util.Objects;