diff --git a/CHANGELOG.md b/CHANGELOG.md index 6a48c1a327..43fc5ccc90 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,10 @@ ## Unreleased +### Fixes + +- [ANR] Removed AndroidTransactionProfiler lock ([#4817](https://github.com/getsentry/sentry-java/pull/4817)) + ### Dependencies - Bump Native SDK from v0.11.2 to v0.11.3 ([#4810](https://github.com/getsentry/sentry-java/pull/4810)) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java index c677252981..2ae1d0d3db 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java @@ -94,7 +94,7 @@ public ProfileEndData( private final @NotNull Map measurementsMap = new HashMap<>(); private final @Nullable ISentryExecutorService timeoutExecutorService; private final @NotNull ILogger logger; - private boolean isRunning = false; + private volatile boolean isRunning = false; protected final @NotNull AutoClosableReentrantLock lock = new AutoClosableReentrantLock(); public AndroidProfiler( @@ -354,4 +354,8 @@ private void putPerformanceCollectionDataInMeasurements( } } } + + boolean isRunning() { + return isRunning; + } } diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java index 0aa678d519..a6d07ba069 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java @@ -5,8 +5,6 @@ import android.annotation.SuppressLint; import android.content.Context; import android.os.Build; -import android.os.Process; -import android.os.SystemClock; import io.sentry.DateUtils; import io.sentry.ILogger; import io.sentry.ISentryExecutorService; @@ -26,9 +24,9 @@ import java.util.ArrayList; import java.util.Date; import java.util.List; +import java.util.concurrent.atomic.AtomicBoolean; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; -import org.jetbrains.annotations.TestOnly; final class AndroidTransactionProfiler implements ITransactionProfiler { private final @NotNull Context context; @@ -39,10 +37,16 @@ final class AndroidTransactionProfiler implements ITransactionProfiler { private final @NotNull ISentryExecutorService executorService; private final @NotNull BuildInfoProvider buildInfoProvider; private boolean isInitialized = false; - private int transactionsCounter = 0; + private final @NotNull AtomicBoolean isRunning = new AtomicBoolean(false); private final @NotNull SentryFrameMetricsCollector frameMetricsCollector; - private @Nullable ProfilingTransactionData currentProfilingTransactionData; - private @Nullable AndroidProfiler profiler = null; + private volatile @Nullable ProfilingTransactionData currentProfilingTransactionData; + + /** + * The underlying profiler instance. It is thread safe to call it after checking if it's not null, + * because we never nullify it after instantiation. + */ + private volatile @Nullable AndroidProfiler profiler = null; + private long profileStartNanos; private long profileStartCpuMillis; private @NotNull Date profileStartTimestamp; @@ -95,6 +99,7 @@ private void init() { return; } isInitialized = true; + if (!isProfilingEnabled) { logger.log(SentryLevel.INFO, "Profiling is disabled in options."); return; @@ -124,22 +129,30 @@ private void init() { @Override public void start() { - try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { - // Debug.startMethodTracingSampling() is only available since Lollipop, but Android Profiler - // causes crashes on api 21 -> https://github.com/getsentry/sentry-java/issues/3392 - if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return; + // Debug.startMethodTracingSampling() is only available since Lollipop, but Android Profiler + // causes crashes on api 21 -> https://github.com/getsentry/sentry-java/issues/3392 + if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return; + // When the first transaction is starting, we can start profiling + if (!isRunning.getAndSet(true)) { // Let's initialize trace folder and profiling interval init(); - transactionsCounter++; - // When the first transaction is starting, we can start profiling - if (transactionsCounter == 1 && onFirstStart()) { + if (onFirstStart()) { logger.log(SentryLevel.DEBUG, "Profiler started."); } else { - transactionsCounter--; - logger.log( - SentryLevel.WARNING, "A profile is already running. This profile will be ignored."); + // If profiler is not null and is running, it means that a profile is already running + if (profiler != null && profiler.isRunning()) { + logger.log( + SentryLevel.WARNING, "A profile is already running. This profile will be ignored."); + } else { + try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { + // Ensure we unbind any transaction data, just in case of concurrent starts + currentProfilingTransactionData = null; + } + // Otherwise we update the flag, because it means the profiler is not running + isRunning.set(false); + } } } } @@ -164,11 +177,14 @@ private boolean onFirstStart() { @Override public void bindTransaction(final @NotNull ITransaction transaction) { - try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { - // If the profiler is running, but no profilingTransactionData is set, we bind it here - if (transactionsCounter > 0 && currentProfilingTransactionData == null) { - currentProfilingTransactionData = - new ProfilingTransactionData(transaction, profileStartNanos, profileStartCpuMillis); + // If the profiler is running, but no profilingTransactionData is set, we bind it here + if (isRunning.get() && currentProfilingTransactionData == null) { + try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { + // If the profiler is running, but no profilingTransactionData is set, we bind it here + if (isRunning.get() && currentProfilingTransactionData == null) { + currentProfilingTransactionData = + new ProfilingTransactionData(transaction, profileStartNanos, profileStartCpuMillis); + } } } } @@ -178,15 +194,13 @@ public void bindTransaction(final @NotNull ITransaction transaction) { final @NotNull ITransaction transaction, final @Nullable List performanceCollectionData, final @NotNull SentryOptions options) { - try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { - return onTransactionFinish( - transaction.getName(), - transaction.getEventId().toString(), - transaction.getSpanContext().getTraceId().toString(), - false, - performanceCollectionData, - options); - } + return onTransactionFinish( + transaction.getName(), + transaction.getEventId().toString(), + transaction.getSpanContext().getTraceId().toString(), + false, + performanceCollectionData, + options); } @SuppressLint("NewApi") @@ -197,20 +211,23 @@ public void bindTransaction(final @NotNull ITransaction transaction) { final boolean isTimeout, final @Nullable List performanceCollectionData, final @NotNull SentryOptions options) { - try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { - // check if profiler was created - if (profiler == null) { - return null; - } - // onTransactionStart() is only available since Lollipop_MR1 - // and SystemClock.elapsedRealtimeNanos() since Jelly Bean - // and SUPPORTED_ABIS since KITKAT - if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return null; + // onTransactionStart() is only available since Lollipop_MR1 + // and SystemClock.elapsedRealtimeNanos() since Jelly Bean + // and SUPPORTED_ABIS since KITKAT + if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return null; + + // check if profiler was created + if (profiler == null) { + return null; + } + + final ProfilingTransactionData txData; + try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) { + txData = currentProfilingTransactionData; // Transaction finished, but it's not in the current profile - if (currentProfilingTransactionData == null - || !currentProfilingTransactionData.getId().equals(transactionId)) { + if (txData == null || !txData.getId().equals(transactionId)) { // A transaction is finishing, but it's not profiled. We can skip it logger.log( SentryLevel.INFO, @@ -219,118 +236,90 @@ public void bindTransaction(final @NotNull ITransaction transaction) { traceId); return null; } + currentProfilingTransactionData = null; + } - if (transactionsCounter > 0) { - transactionsCounter--; - } + logger.log(SentryLevel.DEBUG, "Transaction %s (%s) finished.", transactionName, traceId); - logger.log(SentryLevel.DEBUG, "Transaction %s (%s) finished.", transactionName, traceId); + final AndroidProfiler.ProfileEndData endData = + profiler.endAndCollect(false, performanceCollectionData); - if (transactionsCounter != 0) { - // We notify the data referring to this transaction that it finished - if (currentProfilingTransactionData != null) { - currentProfilingTransactionData.notifyFinish( - SystemClock.elapsedRealtimeNanos(), - profileStartNanos, - Process.getElapsedCpuTime(), - profileStartCpuMillis); - } - return null; - } - - final AndroidProfiler.ProfileEndData endData = - profiler.endAndCollect(false, performanceCollectionData); - // check if profiler end successfully - if (endData == null) { - return null; - } + isRunning.set(false); - long transactionDurationNanos = endData.endNanos - profileStartNanos; + // check if profiler end successfully + if (endData == null) { + return null; + } - List transactionList = new ArrayList<>(1); - final ProfilingTransactionData txData = currentProfilingTransactionData; - if (txData != null) { - transactionList.add(txData); - } - currentProfilingTransactionData = null; - // We clear the counter in case of a timeout - transactionsCounter = 0; - - String totalMem = "0"; - final @Nullable Long memory = - (options instanceof SentryAndroidOptions) - ? DeviceInfoUtil.getInstance(context, (SentryAndroidOptions) options).getTotalMemory() - : null; - if (memory != null) { - totalMem = Long.toString(memory); - } - String[] abis = Build.SUPPORTED_ABIS; + long transactionDurationNanos = endData.endNanos - profileStartNanos; - // We notify all transactions data that all transactions finished. - // Some may not have been really finished, in case of a timeout - for (ProfilingTransactionData t : transactionList) { - t.notifyFinish( - endData.endNanos, profileStartNanos, endData.endCpuMillis, profileStartCpuMillis); - } + final @NotNull List transactionList = new ArrayList<>(1); + transactionList.add(txData); + txData.notifyFinish( + endData.endNanos, profileStartNanos, endData.endCpuMillis, profileStartCpuMillis); - // cpu max frequencies are read with a lambda because reading files is involved, so it will be - // done in the background when the trace file is read - return new ProfilingTraceData( - endData.traceFile, - profileStartTimestamp, - transactionList, - transactionName, - transactionId, - traceId, - Long.toString(transactionDurationNanos), - buildInfoProvider.getSdkInfoVersion(), - abis != null && abis.length > 0 ? abis[0] : "", - () -> CpuInfoUtils.getInstance().readMaxFrequencies(), - buildInfoProvider.getManufacturer(), - buildInfoProvider.getModel(), - buildInfoProvider.getVersionRelease(), - buildInfoProvider.isEmulator(), - totalMem, - options.getProguardUuid(), - options.getRelease(), - options.getEnvironment(), - (endData.didTimeout || isTimeout) - ? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT - : ProfilingTraceData.TRUNCATION_REASON_NORMAL, - endData.measurementsMap); + String totalMem = "0"; + final @Nullable Long memory = + (options instanceof SentryAndroidOptions) + ? DeviceInfoUtil.getInstance(context, (SentryAndroidOptions) options).getTotalMemory() + : null; + if (memory != null) { + totalMem = Long.toString(memory); } + final String[] abis = Build.SUPPORTED_ABIS; + + // cpu max frequencies are read with a lambda because reading files is involved, so it will be + // done in the background when the trace file is read + return new ProfilingTraceData( + endData.traceFile, + profileStartTimestamp, + transactionList, + transactionName, + transactionId, + traceId, + Long.toString(transactionDurationNanos), + buildInfoProvider.getSdkInfoVersion(), + abis != null && abis.length > 0 ? abis[0] : "", + () -> CpuInfoUtils.getInstance().readMaxFrequencies(), + buildInfoProvider.getManufacturer(), + buildInfoProvider.getModel(), + buildInfoProvider.getVersionRelease(), + buildInfoProvider.isEmulator(), + totalMem, + options.getProguardUuid(), + options.getRelease(), + options.getEnvironment(), + (endData.didTimeout || isTimeout) + ? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT + : ProfilingTraceData.TRUNCATION_REASON_NORMAL, + endData.measurementsMap); } @Override public boolean isRunning() { - return transactionsCounter != 0; + return isRunning.get(); } @Override public void close() { + final @Nullable ProfilingTransactionData txData = currentProfilingTransactionData; // we stop profiling - if (currentProfilingTransactionData != null) { + if (txData != null) { onTransactionFinish( - currentProfilingTransactionData.getName(), - currentProfilingTransactionData.getId(), - currentProfilingTransactionData.getTraceId(), + txData.getName(), + txData.getId(), + txData.getTraceId(), true, null, ScopesAdapter.getInstance().getOptions()); - } else if (transactionsCounter != 0) { - // in case the app start profiling is running, and it's not bound to a transaction, we still - // stop profiling, but we also have to manually update the counter. - transactionsCounter--; } + // in case the app start profiling is running, and it's not bound to a transaction, we still + // stop profiling, but we also have to manually update the flag. + isRunning.set(false); // we have to first stop profiling otherwise we would lost the last profile if (profiler != null) { profiler.close(); } } - - @TestOnly - int getTransactionsCounter() { - return transactionsCounter; - } } diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt index 50c7ba3c7d..c7a0f2b456 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt @@ -185,7 +185,7 @@ class AndroidTransactionProfilerTest { fun `profiler start update inner counter`() { val profiler = fixture.getSut(context) profiler.start() - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) } @Test @@ -193,10 +193,10 @@ class AndroidTransactionProfilerTest { val profiler = fixture.getSut(context) profiler.start() profiler.bindTransaction(fixture.transaction1) - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) assertTrue(profiler.isRunning) profiler.onTransactionFinish(fixture.transaction1, null, fixture.options) - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) assertFalse(profiler.isRunning) } @@ -205,19 +205,19 @@ class AndroidTransactionProfilerTest { val profiler = fixture.getSut(context) profiler.start() profiler.start() - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) } @Test fun `profiler bind set current transaction`() { val profiler = fixture.getSut(context) - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) profiler.start() profiler.bindTransaction(fixture.transaction1) - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) val profilingTraceData = profiler.onTransactionFinish(fixture.transaction1, null, fixture.options) - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) assertNotNull(profilingTraceData) assertEquals(profilingTraceData.transactionId, fixture.transaction1.eventId.toString()) @@ -226,18 +226,18 @@ class AndroidTransactionProfilerTest { @Test fun `profiler multiple binds are ignored`() { val profiler = fixture.getSut(context) - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) profiler.start() profiler.bindTransaction(fixture.transaction1) profiler.bindTransaction(fixture.transaction2) - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) val profilingTraceData2 = profiler.onTransactionFinish(fixture.transaction2, null, fixture.options) - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) val profilingTraceData = profiler.onTransactionFinish(fixture.transaction1, null, fixture.options) - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) assertNotNull(profilingTraceData) assertNull(profilingTraceData2) @@ -252,7 +252,7 @@ class AndroidTransactionProfilerTest { } val profiler = fixture.getSut(context, buildInfo) profiler.start() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) } @Test @@ -260,7 +260,7 @@ class AndroidTransactionProfilerTest { fixture.options.apply { profilesSampleRate = 0.0 } val profiler = fixture.getSut(context) profiler.start() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) } @Test @@ -323,7 +323,7 @@ class AndroidTransactionProfilerTest { fixture.options.apply { cacheDirPath = null } val profiler = fixture.getSut(context) profiler.start() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) } @Test @@ -331,7 +331,7 @@ class AndroidTransactionProfilerTest { fixture.options.apply { cacheDirPath = null } val profiler = fixture.getSut(context) profiler.start() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) } @Test @@ -339,7 +339,7 @@ class AndroidTransactionProfilerTest { fixture.options.apply { profilingTracesHz = 0 } val profiler = fixture.getSut(context) profiler.start() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) } @Test @@ -507,10 +507,10 @@ class AndroidTransactionProfilerTest { val profiler = fixture.getSut(context) profiler.start() profiler.bindTransaction(fixture.transaction1) - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) profiler.close() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) // The timeout scheduled job should be cleared val androidProfiler = profiler.getProperty("profiler") @@ -527,10 +527,10 @@ class AndroidTransactionProfilerTest { fun `profiler stops profiling on close, even if not bound to a transaction`() { val profiler = fixture.getSut(context) profiler.start() - assertEquals(1, profiler.transactionsCounter) + assertTrue(profiler.isRunning) profiler.close() - assertEquals(0, profiler.transactionsCounter) + assertFalse(profiler.isRunning) // The timeout scheduled job should be cleared val androidProfiler = profiler.getProperty("profiler")