Profiling - OTEL profiling fix, Stabilization, Logging (#4746)

* add skipProfiling flag to TransactionOptions to be able to skip profiling and handle cases where profiling has been started by otel

* add profilerId to spanContext so that otel span processor can propagate this to the exporter and SentryTracer

* immediately end profiling when stopProfiler is called

* bump api, fix android api 24 code

* catch all exception happening when converting from jfr

* simplify JavaContinuous profiler by catching AsyncProfiler instantiation exceptions in provider

* add exists and writable info to log message

* add method to safely delete file

* remove setNative call

* fix test

* fix reference to commit we vendored from

* drop event if it cannot be processed to not lose the whole chunk

* Format code

* fix test

* Format code

* fix test

* catch exceptions in startProfiler/stopProfiler

* fallback to threadId -1 if it cannot be resolved

---------

Co-authored-by: Sentry Github Bot <[email protected]>

Author: lbloder

sentry-async-profiler/src/main/java/io/sentry/asyncprofiler/convert/JfrAsyncProfilerToSentryProfileConverter.java

@@ -26,6 +26,7 @@
 
 public final class JfrAsyncProfilerToSentryProfileConverter extends JfrConverter {
   private static final double NANOS_PER_SECOND = 1_000_000_000.0;
+  private static final long UNKNOWN_THREAD_ID = -1;
 
   private final @NotNull SentryProfile sentryProfile = new SentryProfile();
   private final @NotNull SentryStackTraceFactory stackTraceFactory;
@@ -113,13 +114,16 @@ public void visit(Event event, long samples, long value) {
       }
     }
 
-    private long resolveThreadId(int eventThreadId) {
-      return jfr.threads.get(eventThreadId) != null
-          ? jfr.javaThreads.get(eventThreadId)
-          : eventThreadId;
+    private long resolveThreadId(int eventId) {
+      Long javaThreadId = jfr.javaThreads.get(eventId);
+      return javaThreadId != null ? javaThreadId : UNKNOWN_THREAD_ID;
     }
 
     private void processThreadMetadata(Event event, long threadId) {
+      if (threadId == UNKNOWN_THREAD_ID) {
+        return;
+      }
+
       final String threadName = getPlainThreadName(event.tid);
       sentryProfile
           .getThreadMetadata()

sentry-async-profiler/src/main/java/io/sentry/asyncprofiler/profiling/JavaContinuousProfiler.java

@@ -56,9 +56,8 @@ public final class JavaContinuousProfiler
 
   private @NotNull String filename = "";
 
-  private @Nullable AsyncProfiler profiler;
+  private @NotNull AsyncProfiler profiler;
   private volatile boolean shouldSample = true;
-  private boolean shouldStop = false;
   private boolean isSampled = false;
   private int rootSpanCounter = 0;
 
@@ -69,27 +68,20 @@ public JavaContinuousProfiler(
       final @NotNull ILogger logger,
       final @Nullable String profilingTracesDirPath,
       final int profilingTracesHz,
-      final @NotNull ISentryExecutorService executorService) {
+      final @NotNull ISentryExecutorService executorService)
+      throws Exception {
     this.logger = logger;
     this.profilingTracesDirPath = profilingTracesDirPath;
     this.profilingTracesHz = profilingTracesHz;
     this.executorService = executorService;
     initializeProfiler();
   }
 
-  private void initializeProfiler() {
-    try {
-      this.profiler = AsyncProfiler.getInstance();
-      // Check version to verify profiler is working
-      String version = profiler.execute("version");
-      logger.log(SentryLevel.DEBUG, "AsyncProfiler initialized successfully. Version: " + version);
-    } catch (Exception e) {
-      logger.log(
-          SentryLevel.WARNING,
-          "Failed to initialize AsyncProfiler. Profiling will be disabled.",
-          e);
-      this.profiler = null;
-    }
+  private void initializeProfiler() throws Exception {
+    this.profiler = AsyncProfiler.getInstance();
+    // Check version to verify profiler is working
+    String version = profiler.execute("version");
+    logger.log(SentryLevel.DEBUG, "AsyncProfiler initialized successfully. Version: " + version);
   }
 
   private boolean init() {
@@ -98,11 +90,6 @@ private boolean init() {
     }
     isInitialized = true;
 
-    if (profiler == null) {
-      logger.log(SentryLevel.ERROR, "Disabling profiling because AsyncProfiler is not available.");
-      return false;
-    }
-
     if (profilingTracesDirPath == null) {
       logger.log(
           SentryLevel.WARNING,
@@ -168,10 +155,11 @@ public void startProfiler(
       }
 
       if (!isRunning()) {
-        shouldStop = false;
         logger.log(SentryLevel.DEBUG, "Started Profiler.");
         start();
       }
+    } catch (Exception e) {
+      logger.log(SentryLevel.ERROR, "Error starting profiler: ", e);
     }
   }
 
@@ -210,11 +198,6 @@ private void start() {
       startProfileChunkTimestamp = new SentryNanotimeDate();
     }
 
-    if (profiler == null) {
-      logger.log(SentryLevel.ERROR, "Cannot start profiling: AsyncProfiler is not available");
-      return;
-    }
-
     filename = profilingTracesDirPath + File.separator + SentryUUID.generateSentryId() + ".jfr";
 
     File jfrFile = new File(filename);
@@ -250,7 +233,8 @@ private void start() {
           SentryLevel.ERROR,
           "Failed to schedule profiling chunk finish. Did you call Sentry.close()?",
           e);
-      shouldStop = true;
+      // If we can't schedule the auto-stop, stop immediately without restart
+      stop(false);
     }
   }
 
@@ -269,10 +253,12 @@ public void stopProfiler(final @NotNull ProfileLifecycle profileLifecycle) {
           if (rootSpanCounter < 0) {
             rootSpanCounter = 0;
           }
-          shouldStop = true;
+          // Stop immediately without restart
+          stop(false);
           break;
         case MANUAL:
-          shouldStop = true;
+          // Stop immediately without restart
+          stop(false);
           break;
       }
     }
@@ -293,11 +279,6 @@ private void stop(final boolean restartProfiler) {
 
       File jfrFile = new File(filename);
 
-      if (profiler == null) {
-        logger.log(SentryLevel.WARNING, "Profiler is null when trying to stop");
-        return;
-      }
-
       try {
         profiler.execute("stop,jfr");
       } catch (Exception e) {
@@ -339,14 +320,16 @@ private void stop(final boolean restartProfiler) {
         sendChunks(scopes, scopes.getOptions());
       }
 
-      if (restartProfiler && !shouldStop) {
+      if (restartProfiler) {
         logger.log(SentryLevel.DEBUG, "Profile chunk finished. Starting a new one.");
         start();
       } else {
         // When the profiler is stopped manually, we have to reset its id
         profilerId = SentryId.EMPTY_ID;
         logger.log(SentryLevel.DEBUG, "Profile chunk finished.");
       }
+    } catch (Exception e) {
+      logger.log(SentryLevel.ERROR, "Error stopping profiler: ", e);
     }
   }
 
@@ -359,9 +342,8 @@ public void reevaluateSampling() {
   public void close(final boolean isTerminating) {
     try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
       rootSpanCounter = 0;
-      shouldStop = true;
+      stop(false);
       if (isTerminating) {
-        stop(false);
         isClosed.set(true);
       }
     }
@@ -412,7 +394,7 @@ private void safelyRemoveFile(File file) {
   @Override
   public boolean isRunning() {
     try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
-      return isRunning && profiler != null && !filename.isEmpty();
+      return isRunning && !filename.isEmpty();
     }
   }
 

sentry-async-profiler/src/main/java/io/sentry/asyncprofiler/provider/AsyncProfilerContinuousProfilerProvider.java

@@ -3,6 +3,8 @@
 import io.sentry.IContinuousProfiler;
 import io.sentry.ILogger;
 import io.sentry.ISentryExecutorService;
+import io.sentry.NoOpContinuousProfiler;
+import io.sentry.SentryLevel;
 import io.sentry.asyncprofiler.profiling.JavaContinuousProfiler;
 import io.sentry.profiling.JavaContinuousProfilerProvider;
 import io.sentry.profiling.JavaProfileConverterProvider;
@@ -22,7 +24,15 @@ public final class AsyncProfilerContinuousProfilerProvider
       String profilingTracesDirPath,
       int profilingTracesHz,
       ISentryExecutorService executorService) {
-    return new JavaContinuousProfiler(
-        logger, profilingTracesDirPath, profilingTracesHz, executorService);
+    try {
+      return new JavaContinuousProfiler(
+          logger, profilingTracesDirPath, profilingTracesHz, executorService);
+    } catch (Exception e) {
+      logger.log(
+          SentryLevel.WARNING,
+          "Failed to initialize AsyncProfiler. Profiling will be disabled.",
+          e);
+      return NoOpContinuousProfiler.getInstance();
+    }
   }
 }

sentry-async-profiler/src/test/java/io/sentry/asyncprofiler/profiling/JavaContinuousProfilerTest.kt

@@ -117,9 +117,6 @@ class JavaContinuousProfilerTest {
     assertTrue(profiler.isRunning)
     // We are scheduling the profiler to stop at the end of the chunk, so it should still be running
     profiler.stopProfiler(ProfileLifecycle.MANUAL)
-    assertTrue(profiler.isRunning)
-    // We run the executor service to trigger the chunk finish, and the profiler shouldn't restart
-    fixture.executor.runAll()
     assertFalse(profiler.isRunning)
   }
 
@@ -325,27 +322,24 @@ class JavaContinuousProfilerTest {
     assertTrue(profiler.isRunning)
     // We run the executor service to trigger the profiler restart (chunk finish)
     fixture.executor.runAll()
+    // At this point the chunk has been submitted to the executor, but yet to be sent
     verify(fixture.scopes, never()).captureProfileChunk(any())
     profiler.stopProfiler(ProfileLifecycle.MANUAL)
-    // We stop the profiler, which should send a chunk
+    // We stop the profiler, which should send both the first and last chunk
     fixture.executor.runAll()
-    verify(fixture.scopes).captureProfileChunk(any())
+    verify(fixture.scopes, times(2)).captureProfileChunk(any())
   }
 
   @Test
   fun `close without terminating stops all profiles after chunk is finished`() {
     val profiler = fixture.getSut()
     profiler.startProfiler(ProfileLifecycle.TRACE, fixture.mockTracesSampler)
     assertTrue(profiler.isRunning)
-    // We are scheduling the profiler to stop at the end of the chunk, so it should still be running
+    // We are closing the profiler, which should stop all profiles after the chunk is finished
     profiler.close(false)
-    assertTrue(profiler.isRunning)
+    assertFalse(profiler.isRunning)
     // However, close() already resets the rootSpanCounter
     assertEquals(0, profiler.rootSpanCounter)
-
-    // We run the executor service to trigger the chunk finish, and the profiler shouldn't restart
-    fixture.executor.runAll()
-    assertFalse(profiler.isRunning)
   }
 
   @Test

sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/OtelSentrySpanProcessor.java

@@ -117,6 +117,9 @@ public void onStart(final @NotNull Context parentContext, final @NotNull ReadWri
             sentryParentSpanId,
             baggage);
     sentrySpan.getSpanContext().setOrigin(SentrySpanExporter.TRACE_ORIGIN);
+    sentrySpan
+        .getSpanContext()
+        .setProfilerId(scopes.getOptions().getContinuousProfiler().getProfilerId());
     spanStorage.storeSentrySpan(spanContext, sentrySpan);
   }
 

sentry/api/sentry.api

@@ -3967,6 +3967,7 @@ public class io/sentry/SpanContext : io/sentry/JsonSerializable, io/sentry/JsonU
 	public fun getOrigin ()Ljava/lang/String;
 	public fun getParentSpanId ()Lio/sentry/SpanId;
 	public fun getProfileSampled ()Ljava/lang/Boolean;
+	public fun getProfilerId ()Lio/sentry/protocol/SentryId;
 	public fun getSampled ()Ljava/lang/Boolean;
 	public fun getSamplingDecision ()Lio/sentry/TracesSamplingDecision;
 	public fun getSpanId ()Lio/sentry/SpanId;
@@ -3981,6 +3982,7 @@ public class io/sentry/SpanContext : io/sentry/JsonSerializable, io/sentry/JsonU
 	public fun setInstrumenter (Lio/sentry/Instrumenter;)V
 	public fun setOperation (Ljava/lang/String;)V
 	public fun setOrigin (Ljava/lang/String;)V
+	public fun setProfilerId (Lio/sentry/protocol/SentryId;)V
 	public fun setSampled (Ljava/lang/Boolean;)V
 	public fun setSampled (Ljava/lang/Boolean;Ljava/lang/Boolean;)V
 	public fun setSamplingDecision (Lio/sentry/TracesSamplingDecision;)V

sentry/src/main/java/io/sentry/Scopes.java

@@ -938,17 +938,18 @@ public void flush(long timeoutMillis) {
       final @NotNull ISpanFactory spanFactory =
           maybeSpanFactory == null ? getOptions().getSpanFactory() : maybeSpanFactory;
 
-      // If continuous profiling is enabled in trace mode, let's start it. Profiler will sample on
-      // its own.
+      // If continuous profiling is enabled in trace mode, let's start it unless skipProfiling is
+      // true in TransactionOptions.
+      // Profiler will sample on its own.
       // Profiler is started before the transaction is created, so that the profiler id is available
       // when the transaction starts
-      if (samplingDecision.getSampled()) {
-        if (getOptions().isContinuousProfilingEnabled()
-            && getOptions().getProfileLifecycle() == ProfileLifecycle.TRACE) {
-          getOptions()
-              .getContinuousProfiler()
-              .startProfiler(ProfileLifecycle.TRACE, getOptions().getInternalTracesSampler());
-        }
+      if (samplingDecision.getSampled()
+          && getOptions().isContinuousProfilingEnabled()
+          && getOptions().getProfileLifecycle() == ProfileLifecycle.TRACE
+          && transactionContext.getProfilerId().equals(SentryId.EMPTY_ID)) {
+        getOptions()
+            .getContinuousProfiler()
+            .startProfiler(ProfileLifecycle.TRACE, getOptions().getInternalTracesSampler());
       }
 
       transaction =

sentry/src/main/java/io/sentry/SentryTracer.java

@@ -83,8 +83,8 @@ public SentryTracer(
 
     setDefaultSpanData(root);
 
-    final @NotNull SentryId continuousProfilerId =
-        scopes.getOptions().getContinuousProfiler().getProfilerId();
+    final @NotNull SentryId continuousProfilerId = getProfilerId();
+
     if (!continuousProfilerId.equals(SentryId.EMPTY_ID) && Boolean.TRUE.equals(isSampled())) {
       this.contexts.setProfile(new ProfileContext(continuousProfilerId));
     }
@@ -229,7 +229,7 @@ public void finish(
             }
           });
 
-      // any un-finished childs will remain unfinished
+      // any un-finished children will remain unfinished
       // as relay takes care of setting the end-timestamp + deadline_exceeded
       // see
       // https://github.com/getsentry/relay/blob/40697d0a1c54e5e7ad8d183fc7f9543b94fe3839/relay-general/src/store/transactions/processor.rs#L374-L378
@@ -244,7 +244,8 @@ public void finish(
                 .onTransactionFinish(this, performanceCollectionData.get(), scopes.getOptions());
       }
       if (scopes.getOptions().isContinuousProfilingEnabled()
-          && scopes.getOptions().getProfileLifecycle() == ProfileLifecycle.TRACE) {
+          && scopes.getOptions().getProfileLifecycle() == ProfileLifecycle.TRACE
+          && root.getSpanContext().getProfilerId().equals(SentryId.EMPTY_ID)) {
         scopes.getOptions().getContinuousProfiler().stopProfiler(ProfileLifecycle.TRACE);
       }
       if (performanceCollectionData.get() != null) {
@@ -543,8 +544,7 @@ private ISpan createChild(
   /** Sets the default data in the span, including profiler _id, thread id and thread name */
   private void setDefaultSpanData(final @NotNull ISpan span) {
     final @NotNull IThreadChecker threadChecker = scopes.getOptions().getThreadChecker();
-    final @NotNull SentryId profilerId =
-        scopes.getOptions().getContinuousProfiler().getProfilerId();
+    final @NotNull SentryId profilerId = getProfilerId();
     if (!profilerId.equals(SentryId.EMPTY_ID) && Boolean.TRUE.equals(span.isSampled())) {
       span.setData(SpanDataConvention.PROFILER_ID, profilerId.toString());
     }
@@ -553,6 +553,12 @@ private void setDefaultSpanData(final @NotNull ISpan span) {
     span.setData(SpanDataConvention.THREAD_NAME, threadChecker.getCurrentThreadName());
   }
 
+  private @NotNull SentryId getProfilerId() {
+    return !root.getSpanContext().getProfilerId().equals(SentryId.EMPTY_ID)
+        ? root.getSpanContext().getProfilerId()
+        : scopes.getOptions().getContinuousProfiler().getProfilerId();
+  }
+
   @Override
   public @NotNull ISpan startChild(final @NotNull String operation) {
     return this.startChild(operation, (String) null);

sentry/src/main/java/io/sentry/SpanContext.java

@@ -55,6 +55,12 @@ public class SpanContext implements JsonUnknown, JsonSerializable {
 
   protected @Nullable Baggage baggage;
 
+  /**
+   * Set the profiler id associated with this transaction. If set to a non-empty id, this value will
+   * be sent to sentry instead of {@link SentryOptions#getContinuousProfiler}
+   */
+  private @NotNull SentryId profilerId = SentryId.EMPTY_ID;
+
   public SpanContext(
       final @NotNull String operation, final @Nullable TracesSamplingDecision samplingDecision) {
     this(new SentryId(), new SpanId(), operation, null, samplingDecision);
@@ -304,6 +310,14 @@ public int hashCode() {
     return Objects.hash(traceId, spanId, parentSpanId, op, description, getStatus());
   }
 
+  public @NotNull SentryId getProfilerId() {
+    return profilerId;
+  }
+
+  public void setProfilerId(@NotNull SentryId profilerId) {
+    this.profilerId = profilerId;
+  }
+
   // region JsonSerializable
 
   public static final class JsonKeys {