feat: append launch profile data to app start transactions/spans (#3736)

CHANGELOG.md

@@ -2,6 +2,10 @@
 
 ## Unreleased
 
+### Features
+
+- Pre-main profiling data is now attached to the app start transaction (#3736)
+
 ### Fixes
 
 - Don't run onCrashedLastSession for nil Events (#3785)
@@ -47,6 +51,7 @@ We now provide a prebuilt XCFramework for SPM, which speeds up your build and al
 more code in Swift. To make this happen, we had to remove the SentryPrivate target for SPM and
 CocoaPods, which you shouldn't have included directly.
 
+- Remove SentryPrivate library (#3623)
 
 ### Fixes
 

Sources/Sentry/Profiling/SentryLaunchProfiling.m

@@ -14,6 +14,7 @@
 #    import "SentrySampling.h"
 #    import "SentrySamplingContext.h"
 #    import "SentrySwift.h"
+#    import "SentryTime.h"
 #    import "SentryTraceOrigins.h"
 #    import "SentryTracer+Private.h"
 #    import "SentryTracerConfiguration.h"
@@ -116,6 +117,7 @@
 void
 startLaunchProfile(void)
 {
+
     static dispatch_once_t onceToken;
     // this function is called from SentryTracer.load but in the future we may expose access
     // directly to customers, and we'll want to ensure it only runs once. dispatch_once is an
@@ -142,24 +144,29 @@
             return;
         }
 
-        SENTRY_LOG_INFO(@"Starting app launch profile.");
+        SENTRY_LOG_INFO(@"Starting app launch profile at %llu.", getAbsoluteTime());
         launchTracer = [[SentryTracer alloc] initWithTransactionContext:context(tracesRate)
                                                                     hub:nil
                                                           configuration:config(profilesRate)];
     });
 }
 
 void
-stopLaunchProfile(SentryHub *hub)
+stopAndTransmitLaunchProfile(SentryHub *hub)
 {
     if (launchTracer == nil) {
         SENTRY_LOG_DEBUG(@"No launch tracer present to stop.");
         return;
     }
 
-    SENTRY_LOG_DEBUG(@"Finishing launch tracer.");
-
     launchTracer.hub = hub;
+    stopAndDiscardLaunchProfileTracer();
+}
+
+void
+stopAndDiscardLaunchProfileTracer(void)
+{
+    SENTRY_LOG_DEBUG(@"Finishing launch tracer.");
     [launchTracer finish];
 }
 

Sources/Sentry/SentryAppStartMeasurement.m

@@ -13,6 +13,7 @@ @implementation SentryAppStartMeasurement
     BOOL _isPreWarmed;
     NSTimeInterval _duration;
     NSDate *_appStartTimestamp;
+    uint64_t _runtimeInitSystemTimestamp;
     NSDate *_runtimeInitTimestamp;
     NSDate *_moduleInitializationTimestamp;
     NSDate *_sdkStartTimestamp;
@@ -23,6 +24,7 @@ @implementation SentryAppStartMeasurement
 - (instancetype)initWithType:(SentryAppStartType)type
                       isPreWarmed:(BOOL)isPreWarmed
                 appStartTimestamp:(NSDate *)appStartTimestamp
+       runtimeInitSystemTimestamp:(uint64_t)runtimeInitSystemTimestamp
                          duration:(NSTimeInterval)duration
              runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp
     moduleInitializationTimestamp:(NSDate *)moduleInitializationTimestamp
@@ -34,6 +36,7 @@ - (instancetype)initWithType:(SentryAppStartType)type
         _type = type;
         _isPreWarmed = isPreWarmed;
         _appStartTimestamp = appStartTimestamp;
+        _runtimeInitSystemTimestamp = runtimeInitSystemTimestamp;
         _duration = duration;
         _runtimeInitTimestamp = runtimeInitTimestamp;
         _moduleInitializationTimestamp = moduleInitializationTimestamp;

Sources/Sentry/SentryAppStartTracker.m

@@ -213,6 +213,7 @@ - (void)buildAppStartMeasurement:(NSDate *)appStartEnd
             [[SentryAppStartMeasurement alloc] initWithType:appStartType
                                                 isPreWarmed:isPreWarmed
                                           appStartTimestamp:appStartTimestamp
+                                 runtimeInitSystemTimestamp:sysctl.runtimeInitSystemTimestamp
                                                    duration:appStartDuration
                                        runtimeInitTimestamp:runtimeInit
                               moduleInitializationTimestamp:sysctl.moduleInitializationTimestamp

Sources/Sentry/SentryProfiler.mm

@@ -1,6 +1,7 @@
 #import "SentryProfiler+Private.h"
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
+#    import "SentryAppStartMeasurement.h"
 #    import "SentryClient+Private.h"
 #    import "SentryDateUtils.h"
 #    import "SentryDebugImageProvider.h"
@@ -380,7 +381,8 @@ + (void)recordMetrics
 }
 
 + (nullable SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:
-    (SentryTransaction *)transaction
+                                     (SentryTransaction *)transaction
+                                                            startTimestamp:(NSDate *)startTimestamp
 {
     SENTRY_LOG_DEBUG(@"Creating profiling envelope item");
     const auto payload = [self collectProfileBetween:transaction.startSystemTime
@@ -392,7 +394,7 @@ + (nullable SentryEnvelopeItem *)createProfilingEnvelopeItemForTransaction:
         return nil;
     }
 
-    [self updateProfilePayload:payload forTransaction:transaction];
+    [self updateProfilePayload:payload forTransaction:transaction startTimestamp:startTimestamp];
     return [self createEnvelopeItemForProfilePayload:payload];
 }
 
@@ -480,7 +482,8 @@ + (nullable SentryEnvelopeItem *)createEnvelopeItemForProfilePayload:
 #    pragma mark - Private
 
 + (void)updateProfilePayload:(NSMutableDictionary<NSString *, id> *)payload
-              forTransaction:(SentryTransaction *)transaction;
+              forTransaction:(SentryTransaction *)transaction
+              startTimestamp:(NSDate *)startTimestamp
 {
     payload[@"platform"] = transaction.platform;
     payload[@"transaction"] = @{
@@ -489,15 +492,7 @@ + (void)updateProfilePayload:(NSMutableDictionary<NSString *, id> *)payload
         @"name" : transaction.transaction,
         @"active_thread_id" : [transaction.trace.transactionContext sentry_threadInfo].threadId
     };
-    const auto timestamp = transaction.trace.originalStartTimestamp;
-    if (UNLIKELY(timestamp == nil)) {
-        SENTRY_LOG_WARN(@"There was no start timestamp on the provided transaction. Falling back "
-                        @"to old behavior of using the current time.");
-        payload[@"timestamp"]
-            = sentry_toIso8601String([SentryDependencyContainer.sharedInstance.dateProvider date]);
-    } else {
-        payload[@"timestamp"] = sentry_toIso8601String(timestamp);
-    }
+    payload[@"timestamp"] = sentry_toIso8601String(startTimestamp);
 }
 
 - (NSMutableDictionary<NSString *, id> *)serializeBetween:(uint64_t)startSystemTime

Sources/Sentry/SentrySDK.m

@@ -22,7 +22,11 @@
 #import "SentrySwift.h"
 #import "SentryThreadWrapper.h"
 #import "SentryTransactionContext.h"
-#import "SentryUIDeviceWrapper.h"
+
+#if SENTRY_HAS_UIKIT
+#    import "SentryUIDeviceWrapper.h"
+#    import "SentryUIViewControllerPerformanceTracker.h"
+#endif // SENTRY_HAS_UIKIT
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
 #    import "SentryLaunchProfiling.h"
@@ -214,8 +218,19 @@ + (void)startWithOptions:(SentryOptions *)options
 #endif // TARGET_OS_IOS && SENTRY_HAS_UIKIT
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
+        BOOL shouldstopAndTransmitLaunchProfile = YES;
+#    if SENTRY_HAS_UIKIT
+        if (SentryUIViewControllerPerformanceTracker.shared.enableWaitForFullDisplay) {
+            shouldstopAndTransmitLaunchProfile = NO;
+        }
+#    endif // SENTRY_HAS_UIKIT
+
         [SentryDependencyContainer.sharedInstance.dispatchQueueWrapper dispatchAsyncWithBlock:^{
-            stopLaunchProfile(hub);
+            if (shouldstopAndTransmitLaunchProfile) {
+                SENTRY_LOG_DEBUG(@"Stopping launch profile in SentrySDK.start because there will "
+                                 @"be no automatic trace to attach it to.");
+                stopAndTransmitLaunchProfile(hub);
+            }
             configureLaunchProfiling(options);
         }];
 #endif // SENTRY_TARGET_PROFILING_SUPPORTED

Sources/Sentry/SentrySysctl.m

@@ -1,9 +1,11 @@
 #import "SentrySysctl.h"
 #import "SentryCrashSysCtl.h"
+#import "SentryTime.h"
 #include <stdio.h>
 #include <time.h>
 
 static NSDate *moduleInitializationTimestamp;
+static uint64_t runtimeInitSystemTimestamp;
 static NSDate *runtimeInit = nil;
 
 /**
@@ -27,8 +29,13 @@ @implementation SentrySysctl
 
 + (void)load
 {
-    // Invoked whenever this class is added to the Objective-C runtime.
     runtimeInit = [NSDate date];
+
+    // this will be used for launch profiles. those are started from SentryTracer.load, and while
+    // there's no guarantee on whether that or this load method will be called first, the difference
+    // in time has been observed to only be on the order of single milliseconds, not significant
+    // enough to make a difference in outcomes
+    runtimeInitSystemTimestamp = getAbsoluteTime();
 }
 
 - (NSDate *)runtimeInitTimestamp
@@ -48,6 +55,11 @@ - (NSDate *)processStartTimestamp
     return [NSDate dateWithTimeIntervalSince1970:startTime.tv_sec + startTime.tv_usec / 1E6];
 }
 
+- (uint64_t)runtimeInitSystemTimestamp
+{
+    return runtimeInitSystemTimestamp;
+}
+
 - (NSDate *)moduleInitializationTimestamp
 {
     return moduleInitializationTimestamp;

Sources/Sentry/SentryTimeToDisplayTracker.m

@@ -6,6 +6,7 @@
 #    import "SentryFramesTracker.h"
 #    import "SentryLog.h"
 #    import "SentryMeasurementValue.h"
+#    import "SentryProfilingConditionals.h"
 #    import "SentrySpan.h"
 #    import "SentrySpanContext.h"
 #    import "SentrySpanId.h"
@@ -16,6 +17,10 @@
 
 #    import <UIKit/UIKit.h>
 
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+#        import "SentryLaunchProfiling.h"
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
+
 @interface
 SentryTimeToDisplayTracker () <SentryFramesTrackerListener>
 
@@ -128,13 +133,19 @@ - (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate
         [self.initialDisplaySpan finish];
         if (!_waitForFullDisplay) {
             [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self];
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+            stopAndDiscardLaunchProfileTracer();
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
         }
     }
     if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO
         && self.initialDisplaySpan.isFinished == YES) {
         SENTRY_LOG_DEBUG(@"Finishing full display span");
         self.fullDisplaySpan.timestamp = newFrameDate;
         [self.fullDisplaySpan finish];
+#    if SENTRY_TARGET_PROFILING_SUPPORTED
+        stopAndDiscardLaunchProfileTracer();
+#    endif // SENTRY_TARGET_PROFILING_SUPPORTED
     }
 
     if (self.initialDisplaySpan.isFinished == YES && self.fullDisplaySpan.isFinished == YES) {

Sources/Sentry/SentryTracer.m

@@ -98,7 +98,6 @@ @implementation SentryTracer {
     dispatch_block_t _idleTimeoutBlock;
     NSMutableArray<id<SentrySpan>> *_children;
     BOOL _startTimeChanged;
-    NSDate *_originalStartTimestamp;
     NSObject *_idleTimeoutLock;
 
 #if SENTRY_HAS_UIKIT
@@ -189,7 +188,8 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti
 #endif // SENTRY_HAS_UIKIT
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
-    if (_configuration.profilesSamplerDecision.decision == kSentrySampleDecisionYes) {
+    if (_configuration.profilesSamplerDecision.decision == kSentrySampleDecisionYes
+        || isTracingAppLaunch) {
         _internalID = [[SentryId alloc] init];
         if ((_isProfiling = [SentryProfiler startWithTracer:_internalID])) {
             SENTRY_LOG_DEBUG(@"Started profiler for trace %@ with internal id %@",
@@ -563,13 +563,7 @@ - (void)finishInternal
         return;
     }
 
-    BOOL shouldBailWithNilHub = _hub == nil;
-#if SENTRY_TARGET_PROFILING_SUPPORTED
-    if (isTracingAppLaunch) {
-        shouldBailWithNilHub = NO;
-    }
-#endif // SENTRY_TARGET_PROFILING_SUPPORTED
-    if (shouldBailWithNilHub) {
+    if (_hub == nil) {
         SENTRY_LOG_DEBUG(
             @"Hub was nil for tracer %@, nothing to do.", _traceContext.traceId.sentryIdString);
         return;
@@ -607,7 +601,24 @@ - (void)finishInternal
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
     if (self.isProfiling) {
-        [self captureTransactionWithProfile:transaction];
+        NSDate *startTimestamp;
+
+#    if SENTRY_HAS_UIKIT
+        if (appStartMeasurement != nil) {
+            startTimestamp = appStartMeasurement.runtimeInitTimestamp;
+        }
+#    endif // SENTRY_HAS_UIKIT
+
+        if (startTimestamp == nil) {
+            startTimestamp = self.startTimestamp;
+        }
+        if (!SENTRY_ASSERT_RETURN(startTimestamp != nil,
+                @"A transaction with a profile should have a start timestamp already. We will "
+                @"assign the current time but this will be incorrect.")) {
+            startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date];
+        }
+
+        [self captureTransactionWithProfile:transaction startTimestamp:startTimestamp];
         return;
     }
 #endif // SENTRY_TARGET_PROFILING_SUPPORTED
@@ -617,17 +628,19 @@ - (void)finishInternal
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
 - (void)captureTransactionWithProfile:(SentryTransaction *)transaction
+                       startTimestamp:(NSDate *)startTimestamp
 {
     SentryEnvelopeItem *profileEnvelopeItem =
-        [SentryProfiler createProfilingEnvelopeItemForTransaction:transaction];
+        [SentryProfiler createProfilingEnvelopeItemForTransaction:transaction
+                                                   startTimestamp:startTimestamp];
 
     if (!profileEnvelopeItem) {
         [_hub captureTransaction:transaction withScope:_hub.scope];
         return;
     }
 
-    SENTRY_LOG_DEBUG(@"Capturing transaction with profiling data attached for tracer id %@.",
-        self.internalID.sentryIdString);
+    SENTRY_LOG_DEBUG(@"Capturing transaction id %@ with profiling data attached for tracer id %@.",
+        transaction.eventId.sentryIdString, self.internalID.sentryIdString);
     [_hub captureTransaction:transaction
                       withScope:_hub.scope
         additionalEnvelopeItems:@[ profileEnvelopeItem ]];
@@ -653,7 +666,6 @@ - (void)trimEndTimestamp
 
 - (void)updateStartTime:(NSDate *)startTime
 {
-    _originalStartTimestamp = self.startTimestamp;
     super.startTimestamp = startTime;
     _startTimeChanged = YES;
 }
@@ -686,7 +698,19 @@ - (SentryTransaction *)toTransaction
 
 #if SENTRY_TARGET_PROFILING_SUPPORTED
     if (self.isProfiling) {
+        // if we have an app start span, use its app start timestamp. otherwise use the tracer's
+        // start system time as we currently do
+        SENTRY_LOG_DEBUG(@"Tracer start time: %llu", self.startSystemTime);
+
         transaction.startSystemTime = self.startSystemTime;
+#    if SENTRY_HAS_UIKIT
+        if (appStartMeasurement != nil) {
+            SENTRY_LOG_DEBUG(@"Assigning transaction start time as app start system time (%llu)",
+                appStartMeasurement.runtimeInitSystemTimestamp);
+            transaction.startSystemTime = appStartMeasurement.runtimeInitSystemTimestamp;
+        }
+#    endif // SENTRY_HAS_UIKIT
+
         [SentryProfiler recordMetrics];
         transaction.endSystemTime
             = SentryDependencyContainer.sharedInstance.dateProvider.systemTime;
@@ -873,11 +897,6 @@ + (nullable SentryTracer *)getTracer:(id<SentrySpan>)span
     return nil;
 }
 
-- (NSDate *)originalStartTimestamp
-{
-    return _startTimeChanged ? _originalStartTimestamp : self.startTimestamp;
-}
-
 @end
 
 NS_ASSUME_NONNULL_END