Concurrent profiling 2 - added list of transactions (#2218)

* added detection and recording of transactions occurred in a profile * added unit/ui tests * added CollectionUtils.map method
getsentry · Aug 31, 2022 · eba80a2 · eba80a2
1 parent 4abe8f5
commit eba80a2
Show file tree

Hide file tree

Showing 6 changed files with 214 additions and 63 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -11,7 +11,8 @@
 
 ### Features
 
-- Added list of ProfilingTransactionData to the profiling envelope payload ([#2216](https://github.com/getsentry/sentry-java/pull/2216))
+- Concurrent profiling 2 - added list of transactions ([#2218](https://github.com/getsentry/sentry-java/pull/2218))
+- Concurrent profiling 1 - added envelope payload data format ([#2216](https://github.com/getsentry/sentry-java/pull/2216))
 - Send source for transactions ([#2180](https://github.com/getsentry/sentry-java/pull/2180))
 - Add profilesSampleRate and profileSampler options for Android sdk ([#2184](https://github.com/getsentry/sentry-java/pull/2184))
 

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
@@ -16,10 +16,13 @@
 import io.sentry.ProfilingTransactionData;
 import io.sentry.SentryLevel;
 import io.sentry.android.core.internal.util.CpuInfoUtils;
+import io.sentry.util.CollectionUtils;
 import io.sentry.util.Objects;
 import java.io.File;
 import java.util.ArrayList;
+import java.util.HashMap;
 import java.util.List;
+import java.util.Map;
 import java.util.UUID;
 import java.util.concurrent.Future;
 import org.jetbrains.annotations.NotNull;
@@ -45,15 +48,15 @@ final class AndroidTransactionProfiler implements ITransactionProfiler {
   private @Nullable File traceFile = null;
   private @Nullable File traceFilesDir = null;
   private @Nullable Future<?> scheduledFinish = null;
-  private volatile @Nullable ITransaction activeTransaction = null;
   private volatile @Nullable ProfilingTraceData timedOutProfilingData = null;
   private final @NotNull Context context;
   private final @NotNull SentryAndroidOptions options;
   private final @NotNull BuildInfoProvider buildInfoProvider;
   private final @Nullable PackageInfo packageInfo;
   private long transactionStartNanos = 0;
   private boolean isInitialized = false;
-  private @Nullable ProfilingTransactionData transactionData;
+  private int transactionsCounter = 0;
+  private final @NotNull Map<String, ProfilingTransactionData> transactionMap = new HashMap<>();
 
   public AndroidTransactionProfiler(
       final @NotNull Context context,
@@ -115,102 +118,131 @@ public synchronized void onTransactionStart(@NotNull ITransaction transaction) {
       return;
     }
 
-    // If a transaction is currently being profiled, we ignore this call
-    if (activeTransaction != null) {
-      options
-          .getLogger()
-          .log(
-              SentryLevel.WARNING,
-              "Profiling is already active and was started by transaction %s",
-              activeTransaction.getSpanContext().getTraceId().toString());
-      return;
-    }
+    transactionsCounter++;
+    // When the first transaction is starting, we can start profiling
+    if (transactionsCounter == 1) {
 
-    traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace");
+      traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace");
 
-    if (traceFile.exists()) {
-      options
-          .getLogger()
-          .log(SentryLevel.DEBUG, "Trace file already exists: %s", traceFile.getPath());
-      return;
-    }
-    activeTransaction = transaction;
-
-    // We stop the trace after 30 seconds, since such a long trace is very probably a trace
-    // that will never end due to an error
-    scheduledFinish =
+      if (traceFile.exists()) {
         options
-            .getExecutorService()
-            .schedule(
-                () -> timedOutProfilingData = onTransactionFinish(transaction),
-                PROFILING_TIMEOUT_MILLIS);
-
-    transactionStartNanos = SystemClock.elapsedRealtimeNanos();
-    transactionData = new ProfilingTransactionData(transaction, transactionStartNanos);
-    Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
+            .getLogger()
+            .log(SentryLevel.DEBUG, "Trace file already exists: %s", traceFile.getPath());
+        transactionsCounter--;
+        return;
+      }
+
+      // We stop profiling after a timeout to avoid huge profiles to be sent
+      scheduledFinish =
+          options
+              .getExecutorService()
+              .schedule(
+                  () -> timedOutProfilingData = onTransactionFinish(transaction, true),
+                  PROFILING_TIMEOUT_MILLIS);
+
+      transactionStartNanos = SystemClock.elapsedRealtimeNanos();
+
+      ProfilingTransactionData transactionData =
+          new ProfilingTransactionData(transaction, transactionStartNanos);
+      transactionMap.put(transaction.getEventId().toString(), transactionData);
+
+      Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
+    } else {
+      ProfilingTransactionData transactionData =
+          new ProfilingTransactionData(transaction, SystemClock.elapsedRealtimeNanos());
+      transactionMap.put(transaction.getEventId().toString(), transactionData);
+    }
+    options
+        .getLogger()
+        .log(
+            SentryLevel.DEBUG,
+            "Transaction %s (%s) started. Transactions being profiled: %d",
+            transaction.getName(),
+            transaction.getSpanContext().getTraceId().toString(),
+            transactionsCounter);
   }
 
-  @SuppressLint("NewApi")
   @Override
   public synchronized @Nullable ProfilingTraceData onTransactionFinish(
       @NotNull ITransaction transaction) {
+    return onTransactionFinish(transaction, false);
+  }
+
+  @SuppressLint("NewApi")
+  private synchronized @Nullable ProfilingTraceData onTransactionFinish(
+      @NotNull ITransaction transaction, boolean isTimeout) {
 
     // onTransactionStart() is only available since Lollipop
     // and SystemClock.elapsedRealtimeNanos() since Jelly Bean
     if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null;
 
-    final ITransaction finalActiveTransaction = activeTransaction;
     final ProfilingTraceData profilingData = timedOutProfilingData;
 
-    // Profiling finished, but we check if we cached last profiling data due to a timeout
-    if (finalActiveTransaction == null) {
-      // If the cached timed out profiling data refers to the transaction that started it we return
-      // it back, otherwise we would simply lose it
+    // Transaction finished, but it's not in the current profile
+    if (!transactionMap.containsKey(transaction.getEventId().toString())) {
+      // We check if we cached a profiling data due to a timeout with this profile in it
+      // If so, we return it back, otherwise we would simply lose it
       if (profilingData != null) {
-        // The timed out transaction is finishing
-        if (profilingData
-            .getTraceId()
-            .equals(transaction.getSpanContext().getTraceId().toString())) {
+        // Don't use method reference. This can cause issues on Android
+        List<String> ids =
+            CollectionUtils.map(profilingData.getTransactions(), (data) -> data.getId());
+        if (ids.contains(transaction.getEventId().toString())) {
           timedOutProfilingData = null;
           return profilingData;
         } else {
           // Another transaction is finishing before the timed out one
           options
               .getLogger()
               .log(
-                  SentryLevel.ERROR,
-                  "Profiling data with id %s exists but doesn't match the closing transaction %s",
-                  profilingData.getTraceId(),
+                  SentryLevel.INFO,
+                  "A timed out profiling data exists, but the finishing transaction %s (%s) is not part of it",
+                  transaction.getName(),
                   transaction.getSpanContext().getTraceId().toString());
           return null;
         }
       }
-      // A transaction is finishing, but profiling didn't start. Maybe it was started by another one
+      // A transaction is finishing, but it's not profiled. We can skip it
       options
           .getLogger()
           .log(
               SentryLevel.INFO,
-              "Transaction %s finished, but profiling never started for it. Skipping",
+              "Transaction %s (%s) finished, but was not currently being profiled. Skipping",
+              transaction.getName(),
               transaction.getSpanContext().getTraceId().toString());
       return null;
     }
 
-    if (finalActiveTransaction != transaction) {
-      options
-          .getLogger()
-          .log(
-              SentryLevel.DEBUG,
-              "Transaction %s finished, but profiling was started by transaction %s. Skipping",
-              transaction.getSpanContext().getTraceId().toString(),
-              finalActiveTransaction.getSpanContext().getTraceId().toString());
+    if (transactionsCounter > 0) {
+      transactionsCounter--;
+    }
+
+    options
+        .getLogger()
+        .log(
+            SentryLevel.DEBUG,
+            "Transaction %s (%s) finished. Transactions to be profiled: %d",
+            transaction.getName(),
+            transaction.getSpanContext().getTraceId().toString(),
+            transactionsCounter);
+
+    if (transactionsCounter != 0 && !isTimeout) {
+      // We notify the data referring to this transaction that it finished
+      ProfilingTransactionData transactionData =
+          transactionMap.get(transaction.getEventId().toString());
+      if (transactionData != null) {
+        transactionData.notifyFinish(SystemClock.elapsedRealtimeNanos(), transactionStartNanos);
+      }
       return null;
     }
 
     Debug.stopMethodTracing();
     long transactionEndNanos = SystemClock.elapsedRealtimeNanos();
     long transactionDurationNanos = transactionEndNanos - transactionStartNanos;
 
-    activeTransaction = null;
+    List<ProfilingTransactionData> transactionList = new ArrayList<>(transactionMap.values());
+    transactionMap.clear();
+    // We clear the counter in case of a timeout
+    transactionsCounter = 0;
 
     if (scheduledFinish != null) {
       scheduledFinish.cancel(true);
@@ -235,10 +267,10 @@ public synchronized void onTransactionStart(@NotNull ITransaction transaction) {
     }
     String[] abis = Build.SUPPORTED_ABIS;
 
-    List<ProfilingTransactionData> transactionList = new ArrayList<>();
-    if (transactionData != null) {
-      transactionData.notifyFinish(transactionEndNanos, transactionStartNanos);
-      transactionList.add(transactionData);
+    // 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(transactionEndNanos, transactionStartNanos);
     }
 
     // cpu max frequencies are read with a lambda because reading files is involved, so it will be

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
@@ -23,6 +23,7 @@ import kotlin.test.assertEquals
 import kotlin.test.assertFailsWith
 import kotlin.test.assertNotNull
 import kotlin.test.assertNull
+import kotlin.test.assertTrue
 
 @RunWith(AndroidJUnit4::class)
 class AndroidTransactionProfilerTest {
@@ -46,6 +47,7 @@ class AndroidTransactionProfilerTest {
         }
         val transaction1 = SentryTracer(TransactionContext("", ""), mock())
         val transaction2 = SentryTracer(TransactionContext("", ""), mock())
+        val transaction3 = SentryTracer(TransactionContext("", ""), mock())
 
         fun getSut(context: Context, buildInfoProvider: BuildInfoProvider = buildInfo): AndroidTransactionProfiler =
             AndroidTransactionProfiler(context, options, buildInfoProvider)
@@ -57,7 +59,7 @@ class AndroidTransactionProfilerTest {
         AndroidOptionsInitializer.init(fixture.options, context, fixture.mockLogger, false, false)
         // Profiler doesn't start if the folder doesn't exists.
         // Usually it's generated when calling Sentry.init, but for tests we can create it manually.
-        File(fixture.options.profilingTracesDirPath).mkdirs()
+        File(fixture.options.profilingTracesDirPath!!).mkdirs()
     }
 
     @AfterTest
@@ -247,7 +249,7 @@ class AndroidTransactionProfilerTest {
     }
 
     @Test
-    fun `profiling stops and returns data only when starting transaction finishes`() {
+    fun `profiling stops and returns data only when the last transaction finishes`() {
         val profiler = fixture.getSut(context)
         profiler.onTransactionStart(fixture.transaction1)
         profiler.onTransactionStart(fixture.transaction2)
@@ -258,4 +260,27 @@ class AndroidTransactionProfilerTest {
         traceData = profiler.onTransactionFinish(fixture.transaction1)
         assertEquals(fixture.transaction1.eventId.toString(), traceData!!.transactionId)
     }
+
+    @Test
+    fun `profiling records multiple concurrent transactions`() {
+        val profiler = fixture.getSut(context)
+        profiler.onTransactionStart(fixture.transaction1)
+        profiler.onTransactionStart(fixture.transaction2)
+
+        var traceData = profiler.onTransactionFinish(fixture.transaction1)
+        assertNull(traceData)
+
+        profiler.onTransactionStart(fixture.transaction3)
+        traceData = profiler.onTransactionFinish(fixture.transaction3)
+        assertNull(traceData)
+        traceData = profiler.onTransactionFinish(fixture.transaction2)
+        assertEquals(fixture.transaction2.eventId.toString(), traceData!!.transactionId)
+        val expectedTransactions = listOf(
+            fixture.transaction1.eventId.toString(),
+            fixture.transaction3.eventId.toString(),
+            fixture.transaction2.eventId.toString()
+        )
+        assertTrue(traceData.transactions.map { it.id }.containsAll(expectedTransactions))
+        assertTrue(expectedTransactions.containsAll(traceData.transactions.map { it.id }))
+    }
 }
diff --git a/...ests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt b/...ests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt
@@ -14,7 +14,9 @@ import io.sentry.SentryOptions
 import io.sentry.protocol.SentryTransaction
 import org.junit.runner.RunWith
 import kotlin.test.Test
+import kotlin.test.assertContains
 import kotlin.test.assertEquals
+import kotlin.test.assertNotEquals
 import kotlin.test.assertNotNull
 import kotlin.test.assertTrue
 
@@ -71,6 +73,63 @@ class EnvelopeTests : BaseUiTest() {
         }
     }
 
+    @Test
+    fun checkEnvelopeConcurrentTransactions() {
+
+        initSentry(true) { options: SentryOptions ->
+            options.tracesSampleRate = 1.0
+            options.profilesSampleRate = 1.0
+        }
+        relayIdlingResource.increment()
+        relayIdlingResource.increment()
+        relayIdlingResource.increment()
+        val transaction = Sentry.startTransaction("e2etests", "test1")
+        val transaction2 = Sentry.startTransaction("e2etests", "test2")
+        val transaction3 = Sentry.startTransaction("e2etests", "test3")
+        transaction.finish()
+        transaction2.finish()
+        transaction3.finish()
+
+        relay.assert {
+            assertEnvelope {
+                val transactionItem: SentryTransaction = it.assertItem()
+                it.assertNoOtherItems()
+                assertEquals(transaction.eventId.toString(), transactionItem.eventId.toString())
+            }
+            assertEnvelope {
+                val transactionItem: SentryTransaction = it.assertItem()
+                it.assertNoOtherItems()
+                assertEquals(transaction2.eventId.toString(), transactionItem.eventId.toString())
+            }
+            // The profile is sent only in the last transaction envelope
+            assertEnvelope {
+                val transactionItem: SentryTransaction = it.assertItem()
+                val profilingTraceData: ProfilingTraceData = it.assertItem()
+                it.assertNoOtherItems()
+                assertEquals(transaction3.eventId.toString(), transactionItem.eventId.toString())
+                assertEquals(profilingTraceData.transactionId, transactionItem.eventId.toString())
+                assertTrue(profilingTraceData.transactionName == "e2etests")
+
+                // Transaction timestamps should be all different from each other
+                val transactions = profilingTraceData.transactions
+                assertContains(transactions.map { t -> t.id }, transactionItem.eventId.toString())
+                val startTimes = transactions.map { t -> t.relativeStartNs }
+                val endTimes = transactions.mapNotNull { t -> t.relativeEndNs }
+                assertNotEquals(startTimes[0], startTimes[1])
+                assertNotEquals(startTimes[0], startTimes[2])
+                assertNotEquals(startTimes[1], startTimes[2])
+                assertNotEquals(endTimes[0], endTimes[1])
+                assertNotEquals(endTimes[0], endTimes[2])
+                assertNotEquals(endTimes[1], endTimes[2])
+
+                // The first and last transactions should be aligned to the start/stop of profile
+                assertEquals(endTimes.maxOrNull()!! - startTimes.minOrNull()!!, profilingTraceData.durationNs.toLong())
+            }
+            assertNoOtherEnvelopes()
+            assertNoOtherRequests()
+        }
+    }
+
     @Test
     fun sendProfiledTransaction() {
         // This is a dogfooding test

diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api
@@ -3082,12 +3082,17 @@ public abstract class io/sentry/transport/TransportResult {
 
 public final class io/sentry/util/CollectionUtils {
 	public static fun filterMapEntries (Ljava/util/Map;Lio/sentry/util/CollectionUtils$Predicate;)Ljava/util/Map;
+	public static fun map (Ljava/util/List;Lio/sentry/util/CollectionUtils$Mapper;)Ljava/util/List;
 	public static fun newArrayList (Ljava/util/List;)Ljava/util/List;
 	public static fun newConcurrentHashMap (Ljava/util/Map;)Ljava/util/Map;
 	public static fun newHashMap (Ljava/util/Map;)Ljava/util/Map;
 	public static fun size (Ljava/lang/Iterable;)I
 }
 
+public abstract interface class io/sentry/util/CollectionUtils$Mapper {
+	public abstract fun map (Ljava/lang/Object;)Ljava/lang/Object;
+}
+
 public abstract interface class io/sentry/util/CollectionUtils$Predicate {
 	public abstract fun test (Ljava/lang/Object;)Z
 }