From 757fbba33db51a985de761eeac60fc1c5917e223 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Wed, 5 Jun 2024 11:58:43 +0200 Subject: [PATCH 1/5] moved span and transaction finish callback before they are actually finished --- .../core/ActivityLifecycleIntegrationTest.kt | 2 +- .../src/main/java/io/sentry/SentryTracer.java | 27 ++++++++++++++----- sentry/src/main/java/io/sentry/Span.java | 20 +++++++++----- .../test/java/io/sentry/SentryTracerTest.kt | 11 ++++++++ sentry/src/test/java/io/sentry/SpanTest.kt | 13 +++++++++ 5 files changed, 60 insertions(+), 13 deletions(-) diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt index 2d20a16ec5a..f936b6251ce 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt @@ -303,7 +303,7 @@ class ActivityLifecycleIntegrationTest { sut.ttidSpanMap.values.first().finish() sut.ttfdSpanMap.values.first().finish() - // then transaction should not be immediatelly finished + // then transaction should not be immediately finished verify(fixture.hub, never()) .captureTransaction( anyOrNull(), diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 41720e5f497..18527000b25 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -200,6 +200,24 @@ public void finish( if (!root.isFinished() && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished())) { + // We set the new spanFinishedCallback here instead of creation time, calling the old one to + // avoid the user overwrites it by setting a custom spanFinishedCallback on the root span + final @Nullable SpanFinishedCallback oldCallback = this.root.getSpanFinishedCallback(); + this.root.setSpanFinishedCallback( + span -> { + if (oldCallback != null) { + oldCallback.execute(span); + } + + // Let's call the finishCallback here, when the root span has a finished date but it's + // not finished, yet + final @Nullable TransactionFinishedCallback finishedCallback = + transactionOptions.getTransactionFinishedCallback(); + if (finishedCallback != null) { + finishedCallback.execute(this); + } + }); + // any un-finished childs will remain unfinished // as relay takes care of setting the end-timestamp + deadline_exceeded // see @@ -232,11 +250,6 @@ public void finish( }); }); final SentryTransaction transaction = new SentryTransaction(this); - final TransactionFinishedCallback finishedCallback = - transactionOptions.getTransactionFinishedCallback(); - if (finishedCallback != null) { - finishedCallback.execute(this); - } if (timer != null) { synchronized (timerLock) { @@ -605,7 +618,9 @@ private boolean hasAllChildrenFinished() { final List spans = new ArrayList<>(this.children); if (!spans.isEmpty()) { for (final Span span : spans) { - if (!span.isFinished()) { + // This is used in the spanFinishCallback, when the span isn't finished, but has a finish + // date + if (!span.isFinished() && span.getFinishDate() == null) { return false; } } diff --git a/sentry/src/main/java/io/sentry/Span.java b/sentry/src/main/java/io/sentry/Span.java index 850276dac3a..14cf4825bff 100644 --- a/sentry/src/main/java/io/sentry/Span.java +++ b/sentry/src/main/java/io/sentry/Span.java @@ -37,7 +37,9 @@ public final class Span implements ISpan { private final @NotNull IHub hub; - private final @NotNull AtomicBoolean finished = new AtomicBoolean(false); + private boolean finished = false; + + private final @NotNull AtomicBoolean isFinishing = new AtomicBoolean(false); private final @NotNull SpanOptions options; @@ -122,7 +124,7 @@ public Span( final @Nullable SentryDate timestamp, final @NotNull Instrumenter instrumenter, @NotNull SpanOptions spanOptions) { - if (finished.get()) { + if (finished) { return NoOpSpan.getInstance(); } @@ -133,7 +135,7 @@ public Span( @Override public @NotNull ISpan startChild( final @NotNull String operation, final @Nullable String description) { - if (finished.get()) { + if (finished) { return NoOpSpan.getInstance(); } @@ -143,7 +145,7 @@ public Span( @Override public @NotNull ISpan startChild( @NotNull String operation, @Nullable String description, @NotNull SpanOptions spanOptions) { - if (finished.get()) { + if (finished) { return NoOpSpan.getInstance(); } return transaction.startChild(context.getSpanId(), operation, description, spanOptions); @@ -192,7 +194,7 @@ public void finish(@Nullable SpanStatus status) { @Override public void finish(final @Nullable SpanStatus status, final @Nullable SentryDate timestamp) { // the span can be finished only once - if (!finished.compareAndSet(false, true)) { + if (finished || !isFinishing.compareAndSet(false, true)) { return; } @@ -235,6 +237,7 @@ public void finish(final @Nullable SpanStatus status, final @Nullable SentryDate if (spanFinishedCallback != null) { spanFinishedCallback.execute(this); } + finished = true; } @Override @@ -284,7 +287,7 @@ public void setTag(final @NotNull String key, final @NotNull String value) { @Override public boolean isFinished() { - return finished.get(); + return finished; } public @NotNull Map getData() { @@ -409,6 +412,11 @@ void setSpanFinishedCallback(final @Nullable SpanFinishedCallback callback) { this.spanFinishedCallback = callback; } + @Nullable + SpanFinishedCallback getSpanFinishedCallback() { + return spanFinishedCallback; + } + private void updateStartDate(@NotNull SentryDate date) { this.startTimestamp = date; } diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index c8839373836..0942768a8a1 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -1378,4 +1378,15 @@ class SentryTracerTest { assertEquals(5, tracer.children.size) } + + @Test + fun `tracer is not finished when finishCallback is called`() { + val transaction = fixture.getSut(transactionFinishedCallback = { + assertFalse(it.isFinished) + assertNotNull(it.finishDate) + }) + assertFalse(transaction.isFinished) + assertNull(transaction.finishDate) + transaction.finish() + } } diff --git a/sentry/src/test/java/io/sentry/SpanTest.kt b/sentry/src/test/java/io/sentry/SpanTest.kt index ae9d9bd07fc..09bf01c791d 100644 --- a/sentry/src/test/java/io/sentry/SpanTest.kt +++ b/sentry/src/test/java/io/sentry/SpanTest.kt @@ -495,6 +495,19 @@ class SpanTest { assertSame(span.localMetricsAggregator, span.localMetricsAggregator) } + // test to ensure that the span is not finished when the finishCallback is called + @Test + fun `span is not finished when finishCallback is called`() { + val span = fixture.getSut() + span.setSpanFinishedCallback { + assertFalse(span.isFinished) + assertNotNull(span.finishDate) + } + assertFalse(span.isFinished) + assertNull(span.finishDate) + span.finish() + } + private fun getTransaction(transactionContext: TransactionContext = TransactionContext("name", "op")): SentryTracer { return SentryTracer(transactionContext, fixture.hub) } From e08b9fe9479c5ec5afe0fe3779900bea1992a4f5 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Wed, 5 Jun 2024 12:02:37 +0200 Subject: [PATCH 2/5] updated changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d89adb2af82..4bd7976e122 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ ### Fixes +- Move onFinishCallback before span or transaction is finished ([#3459](https://github.com/getsentry/sentry-java/pull/3459)) - Fix faulty `span.frame_delay` calculation for early app start spans ([#3427](https://github.com/getsentry/sentry-java/pull/3427)) - Fix crash when installing `ShutdownHookIntegration` and the VM is shutting down ([#3456](https://github.com/getsentry/sentry-java/pull/3456)) From 021d7529cb7bcb797d64c635629db5cafb723eee Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Wed, 5 Jun 2024 13:38:17 +0200 Subject: [PATCH 3/5] moved performance collection before transaction is finished, fixing frame measurements not being set --- .../core/SpanFrameMetricsCollector.java | 18 ++++++++++++++++++ .../src/main/java/io/sentry/SentryTracer.java | 17 +++++++++-------- 2 files changed, 27 insertions(+), 8 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java index 5535bccb911..cedde626d8f 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java @@ -131,12 +131,26 @@ public void onSpanFinished(final @NotNull ISpan span) { private void captureFrameMetrics(@NotNull final ISpan span) { // TODO lock still required? synchronized (lock) { + String x = ""; + for (ISpan runningSpan : runningSpans) { + x += runningSpan.getOperation() + " - " + runningSpan.getDescription() + ", "; + } + System.out.println( + "SpanFrameMetricsCollector.onSpanFinished - " + + span.getOperation() + + " - " + + span.getDescription() + + " ---> \ncurrent spans: " + + x); + boolean removed = runningSpans.remove(span); + System.out.println(removed); if (!removed) { return; } final @Nullable SentryDate spanFinishDate = span.getFinishDate(); + System.out.println("spanFinishDate == null: " + (spanFinishDate == null)); if (spanFinishDate == null) { return; } @@ -144,6 +158,7 @@ private void captureFrameMetrics(@NotNull final ISpan span) { final long spanStartNanos = toNanoTime(span.getStartDate()); final long spanEndNanos = toNanoTime(spanFinishDate); final long spanDurationNanos = spanEndNanos - spanStartNanos; + System.out.println("spanDurationNanos: " + spanDurationNanos); if (spanDurationNanos <= 0) { return; } @@ -193,6 +208,7 @@ private void captureFrameMetrics(@NotNull final ISpan span) { } int totalFrameCount = frameMetrics.getTotalFrameCount(); + System.out.println("totalFrameCount: " + totalFrameCount); final long nextScheduledFrameNanos = frameMetricsCollector.getLastKnownFrameStartTimeNanos(); // nextScheduledFrameNanos might be -1 if no frames have been scheduled for drawing yet @@ -208,12 +224,14 @@ private void captureFrameMetrics(@NotNull final ISpan span) { frameMetrics.getSlowFrameDelayNanos() + frameMetrics.getFrozenFrameDelayNanos(); final double frameDelayInSeconds = frameDelayNanos / 1e9d; + System.out.println("totalFrameCount: " + totalFrameCount); span.setData(SpanDataConvention.FRAMES_TOTAL, totalFrameCount); span.setData(SpanDataConvention.FRAMES_SLOW, frameMetrics.getSlowFrameCount()); span.setData(SpanDataConvention.FRAMES_FROZEN, frameMetrics.getFrozenFrameCount()); span.setData(SpanDataConvention.FRAMES_DELAY, frameDelayInSeconds); if (span instanceof ITransaction) { + System.out.println("TTTT - totalFrameCount: " + totalFrameCount); span.setMeasurement(MeasurementValue.KEY_FRAMES_TOTAL, totalFrameCount); span.setMeasurement(MeasurementValue.KEY_FRAMES_SLOW, frameMetrics.getSlowFrameCount()); span.setMeasurement(MeasurementValue.KEY_FRAMES_FROZEN, frameMetrics.getFrozenFrameCount()); diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 18527000b25..8086acd02e0 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -200,6 +200,8 @@ public void finish( if (!root.isFinished() && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished())) { + final @NotNull AtomicReference> performanceCollectionData = + new AtomicReference<>(); // We set the new spanFinishedCallback here instead of creation time, calling the old one to // avoid the user overwrites it by setting a custom spanFinishedCallback on the root span final @Nullable SpanFinishedCallback oldCallback = this.root.getSpanFinishedCallback(); @@ -216,6 +218,10 @@ public void finish( if (finishedCallback != null) { finishedCallback.execute(this); } + + if (transactionPerformanceCollector != null) { + performanceCollectionData.set(transactionPerformanceCollector.stop(this)); + } }); // any un-finished childs will remain unfinished @@ -224,20 +230,15 @@ public void finish( // https://github.com/getsentry/relay/blob/40697d0a1c54e5e7ad8d183fc7f9543b94fe3839/relay-general/src/store/transactions/processor.rs#L374-L378 root.finish(finishStatus.spanStatus, finishTimestamp); - List performanceCollectionData = null; - if (transactionPerformanceCollector != null) { - performanceCollectionData = transactionPerformanceCollector.stop(this); - } - ProfilingTraceData profilingTraceData = null; if (Boolean.TRUE.equals(isSampled()) && Boolean.TRUE.equals(isProfileSampled())) { profilingTraceData = hub.getOptions() .getTransactionProfiler() - .onTransactionFinish(this, performanceCollectionData, hub.getOptions()); + .onTransactionFinish(this, performanceCollectionData.get(), hub.getOptions()); } - if (performanceCollectionData != null) { - performanceCollectionData.clear(); + if (performanceCollectionData.get() != null) { + performanceCollectionData.get().clear(); } hub.configureScope( From 1010eab57ff4e48a28a3f678cad5fc9e41104fc3 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 18 Jun 2024 12:13:12 +0200 Subject: [PATCH 4/5] removed prints --- .../core/SpanFrameMetricsCollector.java | 18 ------------------ 1 file changed, 18 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java index cedde626d8f..5535bccb911 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java @@ -131,26 +131,12 @@ public void onSpanFinished(final @NotNull ISpan span) { private void captureFrameMetrics(@NotNull final ISpan span) { // TODO lock still required? synchronized (lock) { - String x = ""; - for (ISpan runningSpan : runningSpans) { - x += runningSpan.getOperation() + " - " + runningSpan.getDescription() + ", "; - } - System.out.println( - "SpanFrameMetricsCollector.onSpanFinished - " - + span.getOperation() - + " - " - + span.getDescription() - + " ---> \ncurrent spans: " - + x); - boolean removed = runningSpans.remove(span); - System.out.println(removed); if (!removed) { return; } final @Nullable SentryDate spanFinishDate = span.getFinishDate(); - System.out.println("spanFinishDate == null: " + (spanFinishDate == null)); if (spanFinishDate == null) { return; } @@ -158,7 +144,6 @@ private void captureFrameMetrics(@NotNull final ISpan span) { final long spanStartNanos = toNanoTime(span.getStartDate()); final long spanEndNanos = toNanoTime(spanFinishDate); final long spanDurationNanos = spanEndNanos - spanStartNanos; - System.out.println("spanDurationNanos: " + spanDurationNanos); if (spanDurationNanos <= 0) { return; } @@ -208,7 +193,6 @@ private void captureFrameMetrics(@NotNull final ISpan span) { } int totalFrameCount = frameMetrics.getTotalFrameCount(); - System.out.println("totalFrameCount: " + totalFrameCount); final long nextScheduledFrameNanos = frameMetricsCollector.getLastKnownFrameStartTimeNanos(); // nextScheduledFrameNanos might be -1 if no frames have been scheduled for drawing yet @@ -224,14 +208,12 @@ private void captureFrameMetrics(@NotNull final ISpan span) { frameMetrics.getSlowFrameDelayNanos() + frameMetrics.getFrozenFrameDelayNanos(); final double frameDelayInSeconds = frameDelayNanos / 1e9d; - System.out.println("totalFrameCount: " + totalFrameCount); span.setData(SpanDataConvention.FRAMES_TOTAL, totalFrameCount); span.setData(SpanDataConvention.FRAMES_SLOW, frameMetrics.getSlowFrameCount()); span.setData(SpanDataConvention.FRAMES_FROZEN, frameMetrics.getFrozenFrameCount()); span.setData(SpanDataConvention.FRAMES_DELAY, frameDelayInSeconds); if (span instanceof ITransaction) { - System.out.println("TTTT - totalFrameCount: " + totalFrameCount); span.setMeasurement(MeasurementValue.KEY_FRAMES_TOTAL, totalFrameCount); span.setMeasurement(MeasurementValue.KEY_FRAMES_SLOW, frameMetrics.getSlowFrameCount()); span.setMeasurement(MeasurementValue.KEY_FRAMES_FROZEN, frameMetrics.getFrozenFrameCount()); From 123cc87a08a789e49cfe1c73886ee23db221ebd4 Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 18 Jun 2024 12:16:56 +0200 Subject: [PATCH 5/5] updated changelog --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4959e5c23b9..03f82d857fc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ### Fixes +- Move onFinishCallback before span or transaction is finished ([#3459](https://github.com/getsentry/sentry-java/pull/3459)) - Move fragment auto span finish to onFragmentStarted ([#3424](https://github.com/getsentry/sentry-java/pull/3424)) - Remove profiling timeout logic and disable profiling on API 21 ([#3478](https://github.com/getsentry/sentry-java/pull/3478)) - Properly reset metric flush flag on metric emission ([#3493](https://github.com/getsentry/sentry-java/pull/3493)) @@ -16,7 +17,6 @@ ### Fixes -- Move onFinishCallback before span or transaction is finished ([#3459](https://github.com/getsentry/sentry-java/pull/3459)) - Fix faulty `span.frame_delay` calculation for early app start spans ([#3427](https://github.com/getsentry/sentry-java/pull/3427)) - Fix crash when installing `ShutdownHookIntegration` and the VM is shutting down ([#3456](https://github.com/getsentry/sentry-java/pull/3456))