Fix faulty span.frame_delay calculation for early app start spans (#3427)

* Fix large frame delay values

* Update changelog

Author: markushi

CHANGELOG.md

@@ -1,9 +1,16 @@
 # Changelog
 
+
+## Unreleased
+
 ### Features
 
 - Publish Gradle module metadata ([#3422](https://github.com/getsentry/sentry-java/pull/3422))
 
+### Fixes
+
+- Fix faulty `span.frame_delay` calculation for early app start spans ([#3427](https://github.com/getsentry/sentry-java/pull/3427))
+
 ## 7.9.0
 
 ### Features

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

@@ -7,9 +7,7 @@
 import io.sentry.NoOpSpan;
 import io.sentry.NoOpTransaction;
 import io.sentry.SentryDate;
-import io.sentry.SentryLongDate;
 import io.sentry.SentryNanotimeDate;
-import io.sentry.SentryTracer;
 import io.sentry.SpanDataConvention;
 import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
 import io.sentry.protocol.MeasurementValue;
@@ -33,7 +31,7 @@ public class SpanFrameMetricsCollector
   // grow indefinitely in case of a long running span
   private static final int MAX_FRAMES_COUNT = 3600;
   private static final long ONE_SECOND_NANOS = TimeUnit.SECONDS.toNanos(1);
-  private static final SentryNanotimeDate UNIX_START_DATE = new SentryNanotimeDate(new Date(0), 0);
+  private static final SentryNanotimeDate EMPTY_NANO_TIME = new SentryNanotimeDate(new Date(0), 0);
 
   private final boolean enabled;
   private final @NotNull Object lock = new Object();
@@ -125,7 +123,7 @@ public void onSpanFinished(final @NotNull ISpan span) {
       } else {
         // otherwise only remove old/irrelevant frames
         final @NotNull ISpan oldestSpan = runningSpans.first();
-        frames.headSet(new Frame(realNanos(oldestSpan.getStartDate()))).clear();
+        frames.headSet(new Frame(toNanoTime(oldestSpan.getStartDate()))).clear();
       }
     }
   }
@@ -138,22 +136,20 @@ private void captureFrameMetrics(@NotNull final ISpan span) {
         return;
       }
 
-      // Ignore spans with no finish date, but SentryTracer is not finished when executing this
-      // callback, yet, so in that case we use the current timestamp.
-      final @Nullable SentryDate spanFinishDate =
-          span instanceof SentryTracer ? new SentryNanotimeDate() : span.getFinishDate();
+      final @Nullable SentryDate spanFinishDate = span.getFinishDate();
       if (spanFinishDate == null) {
         return;
       }
-      final long spanEndNanos = realNanos(spanFinishDate);
 
-      final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics();
-      final long spanStartNanos = realNanos(span.getStartDate());
-      if (spanStartNanos >= spanEndNanos) {
+      final long spanStartNanos = toNanoTime(span.getStartDate());
+      final long spanEndNanos = toNanoTime(spanFinishDate);
+      final long spanDurationNanos = spanEndNanos - spanStartNanos;
+      if (spanDurationNanos <= 0) {
         return;
       }
 
-      final long spanDurationNanos = spanEndNanos - spanStartNanos;
+      final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics();
+
       long frameDurationNanos = lastKnownFrameDurationNanos;
 
       if (!frames.isEmpty()) {
@@ -199,11 +195,15 @@ private void captureFrameMetrics(@NotNull final ISpan span) {
       int totalFrameCount = frameMetrics.getTotalFrameCount();
 
       final long nextScheduledFrameNanos = frameMetricsCollector.getLastKnownFrameStartTimeNanos();
-      totalFrameCount +=
-          addPendingFrameDelay(
-              frameMetrics, frameDurationNanos, spanEndNanos, nextScheduledFrameNanos);
-      totalFrameCount += interpolateFrameCount(frameMetrics, frameDurationNanos, spanDurationNanos);
-
+      // nextScheduledFrameNanos might be -1 if no frames have been scheduled for drawing yet
+      // e.g. can happen during early app start
+      if (nextScheduledFrameNanos != -1) {
+        totalFrameCount +=
+            addPendingFrameDelay(
+                frameMetrics, frameDurationNanos, spanEndNanos, nextScheduledFrameNanos);
+        totalFrameCount +=
+            interpolateFrameCount(frameMetrics, frameDurationNanos, spanDurationNanos);
+      }
       final long frameDelayNanos =
           frameMetrics.getSlowFrameDelayNanos() + frameMetrics.getFrozenFrameDelayNanos();
       final double frameDelayInSeconds = frameDelayNanos / 1e9d;
@@ -305,19 +305,20 @@ private static int addPendingFrameDelay(
    * diff does ¯\_(ツ)_/¯
    *
    * @param date the input date
-   * @return a timestamp in nano precision
+   * @return a non-unix timestamp in nano precision, similar to {@link System#nanoTime()}.
    */
-  private static long realNanos(final @NotNull SentryDate date) {
-    // SentryNanotimeDate nanotime is based on System.nanotime(), like UNIX_START_DATE
+  private static long toNanoTime(final @NotNull SentryDate date) {
+    // SentryNanotimeDate nanotime is based on System.nanotime(), like EMPTY_NANO_TIME,
+    // thus diff will simply return the System.nanotime() value of date
     if (date instanceof SentryNanotimeDate) {
-      return date.diff(UNIX_START_DATE);
+      return date.diff(EMPTY_NANO_TIME);
     }
 
-    // SentryLongDate nanotime is based on current date converted to nanoseconds, which is a
-    // different order than frames based System.nanotime(). So we have to convert the nanotime of
-    // the SentryLongDate to a System.nanotime() compatible one.
-    return date.diff(new SentryLongDate(DateUtils.millisToNanos(System.currentTimeMillis())))
-        + System.nanoTime();
+    // e.g. SentryLongDate is unix time based - upscaled to nanos,
+    // we need to project it back to System.nanotime() format
+    long nowUnixInNanos = DateUtils.millisToNanos(System.currentTimeMillis());
+    long shiftInNanos = nowUnixInNanos - date.nanoTimestamp();
+    return System.nanoTime() - shiftInNanos;
   }
 
   private static class Frame implements Comparable<Frame> {

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

@@ -199,6 +199,13 @@ public void finish(
     this.finishStatus = FinishStatus.finishing(status);
     if (!root.isFinished()
         && (!transactionOptions.isWaitForChildren() || hasAllChildrenFinished())) {
+
+      // any un-finished childs 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
+      root.finish(finishStatus.spanStatus, finishTimestamp);
+
       List<PerformanceCollectionData> performanceCollectionData = null;
       if (transactionPerformanceCollector != null) {
         performanceCollectionData = transactionPerformanceCollector.stop(this);
@@ -215,13 +222,6 @@ public void finish(
         performanceCollectionData.clear();
       }
 
-      // any un-finished childs 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
-
-      root.finish(finishStatus.spanStatus, finishTimestamp);
-
       hub.configureScope(
           scope -> {
             scope.withTransaction(