feat(profiling): Drop profiler ids from spans no profile covers

CHANGELOG.md

@@ -9,6 +9,7 @@
   - `globalHubMode` is enabled by default on Android, where tags, extras, contexts and level set inside the callback were silently dropped
   - Scopes that are explicitly made current, e.g. via `Sentry.setCurrentScopes` or the `SentryContext` coroutine integration, are now also honoured when `globalHubMode` is enabled
   - `Sentry.pushScope`, `Sentry.pushIsolationScope` and `Sentry.popScope` remain no-ops when `globalHubMode` is enabled
+- Drop the `profiler_id` from transactions and spans when no Perfetto profile covers them, e.g. when Android's `ProfilingManager` rate limits the profiling request ([#6015](https://github.com/getsentry/sentry-java/pull/6015))
 
 ## 8.54.0
 

sentry-android-core/api/sentry-android-core.api

@@ -44,6 +44,7 @@ public class io/sentry/android/core/AndroidContinuousProfiler : io/sentry/IConti
 	public fun <init> (Lio/sentry/android/core/BuildInfoProvider;Lio/sentry/android/core/internal/util/SentryFrameMetricsCollector;Lio/sentry/ILogger;Ljava/lang/String;ILio/sentry/util/LazyEvaluator$Evaluator;)V
 	public fun close (Z)V
 	public fun getChunkId ()Lio/sentry/protocol/SentryId;
+	public fun getProfileRecordingState (Lio/sentry/protocol/SentryId;Lio/sentry/SentryDate;Lio/sentry/SentryDate;)Lio/sentry/profiling/ProfileRecordingState;
 	public fun getProfilerId ()Lio/sentry/protocol/SentryId;
 	public fun getRootSpanCounter ()I
 	public fun isRunning ()Z
@@ -369,6 +370,7 @@ public class io/sentry/android/core/PerfettoContinuousProfiler : io/sentry/ICont
 	public fun <init> (Lio/sentry/ILogger;Lio/sentry/android/core/internal/util/SentryFrameMetricsCollector;Lio/sentry/util/LazyEvaluator$Evaluator;Ljava/util/function/Supplier;)V
 	public fun close (Z)V
 	public fun getChunkId ()Lio/sentry/protocol/SentryId;
+	public fun getProfileRecordingState (Lio/sentry/protocol/SentryId;Lio/sentry/SentryDate;Lio/sentry/SentryDate;)Lio/sentry/profiling/ProfileRecordingState;
 	public fun getProfilerId ()Lio/sentry/protocol/SentryId;
 	public fun isRunning ()Z
 	public fun onRateLimitChanged (Lio/sentry/transport/RateLimiter;)V
@@ -380,7 +382,6 @@ public class io/sentry/android/core/PerfettoContinuousProfiler : io/sentry/ICont
 public class io/sentry/android/core/PerfettoProfiler {
 	public fun <init> (Landroid/content/Context;Lio/sentry/ILogger;Lio/sentry/ISentryExecutorService;)V
 	public fun endAndCollect (Ljava/util/function/Consumer;)V
-	public fun start (J)Z
 }
 
 public final class io/sentry/android/core/ScreenshotEventProcessor : io/sentry/EventProcessor {

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

@@ -23,6 +23,7 @@
 import io.sentry.SentryOptions;
 import io.sentry.TracesSampler;
 import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
+import io.sentry.profiling.ProfileRecordingState;
 import io.sentry.protocol.SentryId;
 import io.sentry.transport.RateLimiter;
 import io.sentry.util.AutoClosableReentrantLock;
@@ -358,6 +359,18 @@ public void close(final boolean isTerminating) {
     return chunkId;
   }
 
+  /**
+   * This profiler does not track the outcome of its profiling requests, so the answer is always
+   * unknown.
+   */
+  @Override
+  public @NotNull ProfileRecordingState getProfileRecordingState(
+      final @NotNull SentryId profilerId,
+      final @NotNull SentryDate startTime,
+      final @NotNull SentryDate endTime) {
+    return ProfileRecordingState.UNKNOWN;
+  }
+
   private void sendChunks(final @NotNull IScopes scopes, final @NotNull SentryOptions options) {
     try {
       options

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

@@ -23,9 +23,11 @@
 import io.sentry.SentryNanotimeDate;
 import io.sentry.SentryOptions;
 import io.sentry.TracesSampler;
+import io.sentry.android.core.internal.profiling.ChunkRecord;
 import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
 import io.sentry.profilemeasurements.ProfileMeasurement;
 import io.sentry.profilemeasurements.ProfileMeasurementValue;
+import io.sentry.profiling.ProfileRecordingState;
 import io.sentry.protocol.SentryId;
 import io.sentry.transport.RateLimiter;
 import io.sentry.util.AutoClosableReentrantLock;
@@ -59,18 +61,32 @@
  * <p>Currently, this class doesn't do app-start profiling {@link SentryPerformanceProvider}. It is
  * created during {@code Sentry.init()}.
  *
- * <p>Thread safety: all mutable state is guarded by a single {@link
- * io.sentry.util.AutoClosableReentrantLock}. Public entry points ({@link #startProfiler}, {@link
- * #stopProfiler}, {@link #close}, {@link #onRateLimitChanged}, {@link #reevaluateSampling}, and the
- * getters) acquire the lock themselves and are thread-safe. Private methods {@code startInternal}
- * and {@code stopInternal} require the caller to hold the lock.
+ * <p>Thread safety: the profiler state is guarded by {@link #lock}. Every public entry point
+ * acquires it itself and is thread-safe. Private methods that say {@code Caller must hold} a lock
+ * do not, and must only be reached from a frame that already holds it.
+ *
+ * <p>The chunk history is guarded by its own {@link #chunkHistoryLock}, so that {@link
+ * #getProfileRecordingState} — called for every span of a finishing transaction — never waits for a
+ * chunk start or a chunk stop. A frame holding {@link #lock} may take {@link #chunkHistoryLock},
+ * never the other way around. Each {@link ChunkRecord} guards its own state, as the profiler writes
+ * the outcome of a running chunk into it.
  */
 @ApiStatus.Internal
 @RequiresApi(api = Build.VERSION_CODES.VANILLA_ICE_CREAM)
 public class PerfettoContinuousProfiler
     implements IContinuousProfiler, RateLimiter.IRateLimitObserver {
   private static final long MAX_CHUNK_DURATION_MILLIS = 60000;
 
+  /**
+   * How many chunks we remember the outcome of. Spans only ask about windows they were running in,
+   * so a handful of chunks (a minute each) is plenty.
+   *
+   * <p>The history is therefore assumed to be long enough for every window a span can ask about. A
+   * window whose chunks all fell out of it needs no special treatment, and is judged by the chunks
+   * that are left.
+   */
+  @VisibleForTesting static final int MAX_CHUNK_HISTORY_SIZE = 10;
+
   // Matches the thread name produced by SentryExecutorService's thread factory, used to detect
   // when we are already running on the executor thread.
   private static final String EXECUTOR_THREAD_NAME_PREFIX = "SentryExecutorServiceThreadFactory";
@@ -96,6 +112,11 @@ public class PerfettoContinuousProfiler
 
   private final AutoClosableReentrantLock lock = new AutoClosableReentrantLock();
 
+  private final @NotNull ArrayDeque<ChunkRecord> chunkHistory =
+      new ArrayDeque<>(MAX_CHUNK_HISTORY_SIZE);
+
+  private final AutoClosableReentrantLock chunkHistoryLock = new AutoClosableReentrantLock();
+
   public PerfettoContinuousProfiler(
       final @NotNull ILogger logger,
       final @NotNull SentryFrameMetricsCollector frameMetricsCollector,
@@ -186,8 +207,12 @@ public void close(final boolean isTerminating) {
       activeTraceCount = 0;
       shouldStop = true;
       if (isTerminating) {
-        stopInternal(false);
+        // Closing first, so that a result the OS already delivered cannot mark the chunk that
+        // stopInternal ends as recorded: nothing is sent once the profiler is closed
         isClosed.set(true);
+        stopInternal(false);
+        // The chunk that just ended covers nothing, and a pending collection cannot change that
+        markLastChunkNotRecordedIfUnknown();
       }
     }
   }
@@ -213,6 +238,84 @@ public boolean isRunning() {
     }
   }
 
+  @Override
+  public @NotNull ProfileRecordingState getProfileRecordingState(
+      final @NotNull SentryId profilerId,
+      final @NotNull SentryDate startTime,
+      final @NotNull SentryDate endTime) {
+    try (final @NotNull ISentryLifecycleToken ignored = chunkHistoryLock.acquire()) {
+      if (chunkHistory.isEmpty()) {
+        return ProfileRecordingState.UNKNOWN;
+      }
+
+      boolean hasUnknownChunk = false;
+
+      for (final @NotNull ChunkRecord chunk : chunkHistory) {
+        if (!chunk.getProfilerId().equals(profilerId) || !chunk.overlaps(startTime, endTime)) {
+          continue;
+        }
+        final @NotNull ProfileRecordingState state = chunk.getRecordingState();
+        if (state == ProfileRecordingState.RECORDED) {
+          return ProfileRecordingState.RECORDED;
+        }
+        if (state == ProfileRecordingState.UNKNOWN) {
+          hasUnknownChunk = true;
+        }
+      }
+
+      // A chunk that is still running, or that is still being collected, may yet be recorded
+      if (hasUnknownChunk) {
+        return ProfileRecordingState.UNKNOWN;
+      }
+
+      // Every chunk overlapping the window failed, or no chunk ran during the window at all
+      return ProfileRecordingState.NOT_RECORDED;
+    }
+  }
+
+  /**
+   * Gives up on the newest chunk, unless its outcome is already known. Only that one can still be
+   * unknown, as a chunk gets its outcome before the next one starts.
+   */
+  private void markLastChunkNotRecordedIfUnknown() {
+    try (final @NotNull ISentryLifecycleToken ignored = chunkHistoryLock.acquire()) {
+      final @Nullable ChunkRecord lastChunk = chunkHistory.peekLast();
+      if (lastChunk != null && lastChunk.getRecordingState() == ProfileRecordingState.UNKNOWN) {
+        lastChunk.setRecordingState(ProfileRecordingState.NOT_RECORDED);
+      }
+    }
+  }
+
+  private void addChunkRecord(final @NotNull ChunkRecord chunk) {
+    try (final @NotNull ISentryLifecycleToken ignored = chunkHistoryLock.acquire()) {
+      if (chunkHistory.size() == MAX_CHUNK_HISTORY_SIZE) {
+        chunkHistory.removeFirst();
+      }
+      chunkHistory.addLast(chunk);
+    }
+  }
+
+  private void removeChunkRecord(final @NotNull ChunkRecord chunk) {
+    try (final @NotNull ISentryLifecycleToken ignored = chunkHistoryLock.acquire()) {
+      chunkHistory.remove(chunk);
+    }
+  }
+
+  /**
+   * Ends the running chunk, which is always the newest one, as a chunk only starts once the one
+   * before it ended. Returns null if there is none, or if it already ended.
+   */
+  private @Nullable ChunkRecord endChunkRecord(final @NotNull SentryDate endTimestamp) {
+    try (final @NotNull ISentryLifecycleToken ignored = chunkHistoryLock.acquire()) {
+      final @Nullable ChunkRecord chunk = chunkHistory.peekLast();
+      if (chunk == null || chunk.hasEnded()) {
+        return null;
+      }
+      chunk.setEndTimestamp(endTimestamp);
+      return chunk;
+    }
+  }
+
   /**
    * Resolves scopes on first call. Since PerfettoContinuousProfiler is created during Sentry.init()
    * and never used for app-start profiling, scopes is guaranteed to be available by the time
@@ -265,19 +368,27 @@ private void startInternal() {
     if (perfettoProfiler == null) {
       return;
     }
-    if (!perfettoProfiler.start(MAX_CHUNK_DURATION_MILLIS)) {
-      logger.log(
-          SentryLevel.ERROR,
-          "Failed to start Perfetto profiling. PerfettoProfiler.start() returned false.");
-      return;
+    if (SentryId.EMPTY_ID.equals(profilerId)) {
+      profilerId = new SentryId();
     }
 
-    isRunning = true;
+    // The chunk is known before profiling starts, so that a transaction finishing right after the
+    // request cannot miss the chunk it ran in and drop its profiler id
+    final @NotNull ChunkRecord chunkRecord =
+        new ChunkRecord(profilerId, startProfileChunkTimestamp);
+    addChunkRecord(chunkRecord);
 
-    if (profilerId.equals(SentryId.EMPTY_ID)) {
-      profilerId = new SentryId();
+    if (!perfettoProfiler.start(chunkRecord, MAX_CHUNK_DURATION_MILLIS)) {
+      // No chunk ran, so the record is dropped rather than kept as a failure: it would take a slot
+      // of the history away from the chunks that did run
+      removeChunkRecord(chunkRecord);
+      profilerId = SentryId.EMPTY_ID;
+      chunkId = SentryId.EMPTY_ID;
+      logger.log(SentryLevel.ERROR, "Failed to start Perfetto profiling.");
+      return;
     }
 
+    isRunning = true;
     if (chunkId.equals(SentryId.EMPTY_ID)) {
       chunkId = new SentryId();
     }
@@ -328,6 +439,7 @@ private void stopInternal(final boolean restartProfiler) {
     final @NotNull SentryId chunkProfilerId = profilerId;
     final @NotNull SentryId chunkChunkId = chunkId;
     final @NotNull SentryDate chunkTimestamp = startProfileChunkTimestamp;
+    final @Nullable ChunkRecord chunkRecord = endChunkRecord(options.getDateProvider().now());
 
     isRunning = false;
     perfettoProfiler = null;
@@ -348,6 +460,7 @@ private void stopInternal(final boolean restartProfiler) {
                 traceFile,
                 chunkProfilerId,
                 chunkChunkId,
+                chunkRecord,
                 measurements,
                 chunkTimestamp,
                 shouldRestart,
@@ -359,11 +472,22 @@ private void onChunkCollected(
       final @Nullable File traceFile,
       final @NotNull SentryId chunkProfilerId,
       final @NotNull SentryId chunkChunkId,
+      final @Nullable ChunkRecord chunkRecord,
       final @NotNull Map<String, ProfileMeasurement> measurements,
       final @NotNull SentryDate chunkTimestamp,
       final boolean shouldRestart,
       final @NotNull IScopes scopes,
       final @NotNull SentryOptions options) {
+    // The trace file is the last word on whether the chunk was recorded: the OS may report success
+    // and still leave no usable file behind
+    if (chunkRecord != null) {
+      // Nothing is sent once the profiler is closed, so a collected chunk still covers nothing
+      chunkRecord.setRecordingState(
+          traceFile != null && !isClosed.get()
+              ? ProfileRecordingState.RECORDED
+              : ProfileRecordingState.NOT_RECORDED);
+    }
+
     if (traceFile == null) {
       logger.log(
           SentryLevel.ERROR,