Android Profiler on calling thread

CHANGELOG.md

@@ -17,6 +17,7 @@
 
 ### Fixes
 
+- Android Profiler on calling thread ([#2691](https://github.com/getsentry/sentry-java/pull/2691))
 - Use `configureScope` instead of `withScope` in `Hub.close()`. This ensures that the main scope releases the in-memory data when closing a hub instance. ([#2688](https://github.com/getsentry/sentry-java/pull/2688))
 
 ### Dependencies

sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java

@@ -32,7 +32,6 @@
 import java.util.List;
 import java.util.Map;
 import java.util.UUID;
-import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
 import java.util.concurrent.RejectedExecutionException;
 import java.util.concurrent.TimeUnit;
@@ -144,21 +143,6 @@ private void init() {
 
   @Override
   public synchronized void onTransactionStart(final @NotNull ITransaction transaction) {
-    try {
-      options.getExecutorService().submit(() -> onTransactionStartSafe(transaction));
-    } catch (RejectedExecutionException e) {
-      options
-          .getLogger()
-          .log(
-              SentryLevel.ERROR,
-              "Failed to call the executor. Profiling will not be started. Did you call Sentry.close()?",
-              e);
-    }
-  }
-
-  @SuppressLint("NewApi")
-  private void onTransactionStartSafe(final @NotNull ITransaction transaction) {
-
     // Debug.startMethodTracingSampling() is only available since Lollipop
     if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return;
 
@@ -167,21 +151,22 @@ private void onTransactionStartSafe(final @NotNull ITransaction transaction) {
 
     // traceFilesDir is null or intervalUs is 0 only if there was a problem in the init, but
     // we already logged that
-    if (traceFilesDir == null || intervalUs == 0 || !traceFilesDir.canWrite()) {
+    if (traceFilesDir == null || intervalUs == 0) {
       return;
     }
 
     transactionsCounter++;
     // When the first transaction is starting, we can start profiling
     if (transactionsCounter == 1) {
-      onFirstTransactionStarted(transaction);
-      options
-          .getLogger()
-          .log(
-              SentryLevel.DEBUG,
-              "Transaction %s (%s) started and being profiled.",
-              transaction.getName(),
-              transaction.getSpanContext().getTraceId().toString());
+      if (onFirstTransactionStarted(transaction)) {
+        options
+            .getLogger()
+            .log(
+                SentryLevel.DEBUG,
+                "Transaction %s (%s) started and being profiled.",
+                transaction.getName(),
+                transaction.getSpanContext().getTraceId().toString());
+      }
     } else {
       transactionsCounter--;
       options
@@ -195,7 +180,7 @@ private void onTransactionStartSafe(final @NotNull ITransaction transaction) {
   }
 
   @SuppressLint("NewApi")
-  private void onFirstTransactionStarted(final @NotNull ITransaction transaction) {
+  private boolean onFirstTransactionStarted(final @NotNull ITransaction transaction) {
     // We create a file with a uuid name, so no need to check if it already exists
     traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace");
 
@@ -273,33 +258,28 @@ public void onFrameMetricCollected(
     currentProfilingTransactionData =
         new ProfilingTransactionData(transaction, transactionStartNanos, profileStartCpuMillis);
 
-    Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
+    // We don't make any check on the file existence or writeable state, because we don't want to
+    // make file IO in the main thread.
+    // We cannot offload the work to the executorService, as if that's very busy, profiles could
+    // start/stop with a lot of delay and even cause ANRs.
+    try {
+      // If there is any problem with the file this method will throw (but it will not throw in
+      // tests)
+      Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
+      return true;
+    } catch (Throwable e) {
+      onTransactionFinish(transaction, null);
+      options.getLogger().log(SentryLevel.ERROR, "Unable to start a profile: ", e);
+      return false;
+    }
   }
 
   @Override
   public @Nullable synchronized ProfilingTraceData onTransactionFinish(
       final @NotNull ITransaction transaction,
       final @Nullable List<PerformanceCollectionData> performanceCollectionData) {
-    try {
-      return options
-          .getExecutorService()
-          .submit(() -> onTransactionFinish(transaction, false, performanceCollectionData))
-          .get();
-    } catch (ExecutionException | InterruptedException e) {
-      options.getLogger().log(SentryLevel.ERROR, "Error finishing profiling: ", e);
-      // We stop profiling even on exceptions, so profiles don't run indefinitely
-      onTransactionFinish(transaction, false, null);
-    } catch (RejectedExecutionException e) {
-      options
-          .getLogger()
-          .log(
-              SentryLevel.ERROR,
-              "Failed to call the executor. Profiling could not be finished. Did you call Sentry.close()?",
-              e);
-      // We stop profiling even on exceptions, so profiles don't run indefinitely
-      onTransactionFinish(transaction, false, null);
-    }
-    return null;
+
+    return onTransactionFinish(transaction, false, performanceCollectionData);
   }
 
   @SuppressLint("NewApi")
@@ -370,7 +350,14 @@ public void onFrameMetricCollected(
       return null;
     }
 
-    Debug.stopMethodTracing();
+    try {
+      // If there is any problem with the file this method could throw, but the start is also
+      // wrapped, so this should never happen (except for tests, where this is the only method that
+      // throws)
+      Debug.stopMethodTracing();
+    } catch (Throwable e) {
+      options.getLogger().log(SentryLevel.ERROR, "Error while stopping profiling: ", e);
+    }
     frameMetricsCollector.stopCollection(frameMetricsCollectorId);
 
     long transactionEndNanos = SystemClock.elapsedRealtimeNanos();

sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt

@@ -20,6 +20,7 @@ import io.sentry.test.getCtor
 import io.sentry.test.getProperty
 import org.junit.runner.RunWith
 import org.mockito.kotlin.any
+import org.mockito.kotlin.eq
 import org.mockito.kotlin.mock
 import org.mockito.kotlin.never
 import org.mockito.kotlin.spy
@@ -39,6 +40,7 @@ import kotlin.test.assertFailsWith
 import kotlin.test.assertFalse
 import kotlin.test.assertNotNull
 import kotlin.test.assertNull
+import kotlin.test.assertTrue
 
 @RunWith(AndroidJUnit4::class)
 class AndroidTransactionProfilerTest {
@@ -291,16 +293,27 @@ class AndroidTransactionProfilerTest {
     }
 
     @Test
-    fun `profiler uses background threads`() {
+    fun `profiler never use background threads`() {
         val profiler = fixture.getSut(context)
         val mockExecutorService: ISentryExecutorService = mock()
         fixture.options.executorService = mockExecutorService
         whenever(mockExecutorService.submit(any<Callable<*>>())).thenReturn(mock())
         profiler.onTransactionStart(fixture.transaction1)
-        verify(mockExecutorService).submit(any<Runnable>())
+        verify(mockExecutorService, never()).submit(any<Runnable>())
         val profilingTraceData: ProfilingTraceData? = profiler.onTransactionFinish(fixture.transaction1, null)
-        assertNull(profilingTraceData)
-        verify(mockExecutorService).submit(any<Callable<*>>())
+        assertNotNull(profilingTraceData)
+        verify(mockExecutorService, never()).submit(any<Callable<*>>())
+    }
+
+    @Test
+    fun `profiler does not throw if traces cannot be written to disk`() {
+        File(fixture.options.profilingTracesDirPath!!).setWritable(false)
+        val profiler = fixture.getSut(context)
+        profiler.onTransactionStart(fixture.transaction1)
+        profiler.onTransactionFinish(fixture.transaction1, null)
+        // We assert that no trace files are written
+        assertTrue(File(fixture.options.profilingTracesDirPath!!).list()!!.isEmpty())
+        verify(fixture.mockLogger).log(eq(SentryLevel.ERROR), eq("Error while stopping profiling: "), any())
     }
 
     @Test