From 2f9c5f9dbd28d6d171efd250c25c2aeca9b16f45 Mon Sep 17 00:00:00 2001 From: Philipp Hofmann Date: Thu, 4 Jan 2024 14:10:15 +0100 Subject: [PATCH] feat: Split up UIKit and App Init App Start Spans (#3534) Split the UIKit and Application Init span into one span for UIKit Init and another for Application Init. The UIKit Init span ends when the users start the SentrySDK. We recommend that the SentrySDK is the first to call in the UIApplication.didFinishLaunching method because otherwise, users won't receive any potential crash reports for code running before our SDK. Therefore, we pick the start time of our SDK as when the UIApplicationDelegate.didFinishLaunching is called. Fixes GH-3345 --- CHANGELOG.md | 1 + Sources/Sentry/SentryAppStartMeasurement.m | 3 +++ Sources/Sentry/SentryAppStartTracker.m | 1 + Sources/Sentry/SentryBuildAppStartSpans.m | 12 ++++++++--- Sources/Sentry/SentrySDK.m | 21 +++++++++++++++++++ .../HybridPublic/SentryAppStartMeasurement.h | 6 ++++++ Sources/Sentry/include/SentrySDK+Private.h | 1 + .../SentryProfilerSwiftTests.swift | 3 ++- .../SentryAppStartTrackerTests.swift | 16 +++++++++----- Tests/SentryTests/Protocol/TestData.swift | 5 +++-- Tests/SentryTests/SentrySDKTests.swift | 18 ++++++++++++++++ .../Transaction/SentryTracerTests.swift | 16 ++++++++------ 12 files changed, 86 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c2bff563910..52e588eed3f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Add frames delay to transactions and spans (#3487, #3496) - Add slow and frozen frames to spans (#3450, #3478) +- Split up UIKit and App Init App Start Span (#3534) - Prewarmed App Start Tracing is stable (#3536) ### Fixes diff --git a/Sources/Sentry/SentryAppStartMeasurement.m b/Sources/Sentry/SentryAppStartMeasurement.m index 6649a250604..8c87356a6d4 100644 --- a/Sources/Sentry/SentryAppStartMeasurement.m +++ b/Sources/Sentry/SentryAppStartMeasurement.m @@ -15,6 +15,7 @@ @implementation SentryAppStartMeasurement NSDate *_appStartTimestamp; NSDate *_runtimeInitTimestamp; NSDate *_moduleInitializationTimestamp; + NSDate *_sdkStartTimestamp; NSDate *_didFinishLaunchingTimestamp; } # endif // SENTRY_HAS_UIKIT @@ -25,6 +26,7 @@ - (instancetype)initWithType:(SentryAppStartType)type duration:(NSTimeInterval)duration runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp moduleInitializationTimestamp:(NSDate *)moduleInitializationTimestamp + sdkStartTimestamp:(NSDate *)sdkStartTimestamp didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp { # if SENTRY_HAS_UIKIT @@ -35,6 +37,7 @@ - (instancetype)initWithType:(SentryAppStartType)type _duration = duration; _runtimeInitTimestamp = runtimeInitTimestamp; _moduleInitializationTimestamp = moduleInitializationTimestamp; + _sdkStartTimestamp = sdkStartTimestamp; _didFinishLaunchingTimestamp = didFinishLaunchingTimestamp; } diff --git a/Sources/Sentry/SentryAppStartTracker.m b/Sources/Sentry/SentryAppStartTracker.m index 2786ad66b14..38da3d0f286 100644 --- a/Sources/Sentry/SentryAppStartTracker.m +++ b/Sources/Sentry/SentryAppStartTracker.m @@ -216,6 +216,7 @@ - (void)buildAppStartMeasurement:(NSDate *)appStartEnd duration:appStartDuration runtimeInitTimestamp:runtimeInit moduleInitializationTimestamp:sysctl.moduleInitializationTimestamp + sdkStartTimestamp:SentrySDK.startTimestamp didFinishLaunchingTimestamp:self.didFinishLaunchingTimestamp]; SentrySDK.appStartMeasurement = appStartMeasurement; diff --git a/Sources/Sentry/SentryBuildAppStartSpans.m b/Sources/Sentry/SentryBuildAppStartSpans.m index bfa40a5280f..2d344bef1b1 100644 --- a/Sources/Sentry/SentryBuildAppStartSpans.m +++ b/Sources/Sentry/SentryBuildAppStartSpans.m @@ -74,12 +74,18 @@ [appStartSpans addObject:runtimeInitSpan]; } - SentrySpan *appInitSpan = sentryBuildAppStartSpan( - tracer, appStartSpan.spanId, operation, @"UIKit and Application Init"); + SentrySpan *appInitSpan + = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"UIKit Init"); [appInitSpan setStartTimestamp:appStartMeasurement.moduleInitializationTimestamp]; - [appInitSpan setTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; + [appInitSpan setTimestamp:appStartMeasurement.sdkStartTimestamp]; [appStartSpans addObject:appInitSpan]; + SentrySpan *didFinishLaunching + = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"Application Init"); + [didFinishLaunching setStartTimestamp:appStartMeasurement.sdkStartTimestamp]; + [didFinishLaunching setTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; + [appStartSpans addObject:didFinishLaunching]; + SentrySpan *frameRenderSpan = sentryBuildAppStartSpan(tracer, appStartSpan.spanId, operation, @"Initial Frame Render"); [frameRenderSpan setStartTimestamp:appStartMeasurement.didFinishLaunchingTimestamp]; diff --git a/Sources/Sentry/SentrySDK.m b/Sources/Sentry/SentrySDK.m index 2840b439a1b..4135697d259 100644 --- a/Sources/Sentry/SentrySDK.m +++ b/Sources/Sentry/SentrySDK.m @@ -7,6 +7,7 @@ #import "SentryClient+Private.h" #import "SentryCrash.h" #import "SentryCrashWrapper.h" +#import "SentryCurrentDateProvider.h" #import "SentryDependencyContainer.h" #import "SentryDispatchQueueWrapper.h" #import "SentryFileManager.h" @@ -42,6 +43,7 @@ @implementation SentrySDK * reenable the integrations. */ static NSUInteger startInvocations; +static NSDate *_Nullable startTimestamp = nil; + (void)initialize { @@ -135,6 +137,22 @@ + (void)setStartInvocations:(NSUInteger)value startInvocations = value; } +/** + * Not public, only for internal use. + */ ++ (nullable NSDate *)startTimestamp +{ + return startTimestamp; +} + +/** + * Only needed for testing. + */ ++ (void)setStartTimestamp:(NSDate *)value +{ + startTimestamp = value; +} + + (void)startWithOptions:(SentryOptions *)options { [SentryLog configure:options.debug diagnosticLevel:options.diagnosticLevel]; @@ -145,6 +163,7 @@ + (void)startWithOptions:(SentryOptions *)options SENTRY_LOG_DEBUG(@"Starting SDK..."); startInvocations++; + startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date]; SentryClient *newClient = [[SentryClient alloc] initWithOptions:options]; [newClient.fileManager moveAppStateToPreviousAppState]; @@ -402,6 +421,8 @@ + (void)close { SENTRY_LOG_DEBUG(@"Starting to close SDK."); + startTimestamp = nil; + SentryHub *hub = SentrySDK.currentHub; [hub removeAllIntegrations]; diff --git a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h index f48cdd5f370..edd879dca9a 100644 --- a/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h +++ b/Sources/Sentry/include/HybridPublic/SentryAppStartMeasurement.h @@ -26,6 +26,7 @@ SENTRY_NO_INIT duration:(NSTimeInterval)duration runtimeInitTimestamp:(NSDate *)runtimeInitTimestamp moduleInitializationTimestamp:(NSDate *)moduleInitializationTimestamp + sdkStartTimestamp:(NSDate *)sdkStartTimestamp didFinishLaunchingTimestamp:(NSDate *)didFinishLaunchingTimestamp; /** @@ -58,6 +59,11 @@ SENTRY_NO_INIT */ @property (readonly, nonatomic, strong) NSDate *moduleInitializationTimestamp; +/** + * When the SentrySDK start method is called. + */ +@property (readonly, nonatomic, strong) NSDate *sdkStartTimestamp; + /** * When OS posts UIApplicationDidFinishLaunchingNotification. */ diff --git a/Sources/Sentry/include/SentrySDK+Private.h b/Sources/Sentry/include/SentrySDK+Private.h index de0f263286f..9d0f728acca 100644 --- a/Sources/Sentry/include/SentrySDK+Private.h +++ b/Sources/Sentry/include/SentrySDK+Private.h @@ -21,6 +21,7 @@ SentrySDK () + (nullable SentryAppStartMeasurement *)getAppStartMeasurement; @property (nonatomic, class) NSUInteger startInvocations; +@property (nullable, nonatomic, class) NSDate *startTimestamp; + (SentryHub *)currentHub; diff --git a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift index 8ed4b6c5a20..f7c8d938ed8 100644 --- a/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift +++ b/Tests/SentryProfilerTests/SentryProfilerSwiftTests.swift @@ -228,7 +228,8 @@ class SentryProfilerSwiftTests: XCTestCase { appStart = preWarmed ? main : appStart appStartDuration = preWarmed ? appStartDuration - runtimeInitDuration - mainDuration : appStartDuration appStartEnd = appStart.addingTimeInterval(appStartDuration) - return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, + sdkStartTimestamp: appStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) } diff --git a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift index 8e4bd5d73e9..18106d87d0d 100644 --- a/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift +++ b/Tests/SentryTests/Integrations/Performance/AppStartTracking/SentryAppStartTrackerTests.swift @@ -24,6 +24,7 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { let appStartDuration: TimeInterval = 0.4 var runtimeInitTimestamp: Date var moduleInitializationTimestamp: Date + var sdkStartTimestamp: Date var didFinishLaunchingTimestamp: Date init() { @@ -50,7 +51,10 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { runtimeInitTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) moduleInitializationTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.1) - didFinishLaunchingTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.3) + sdkStartTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.1) + SentrySDK.startTimestamp = sdkStartTimestamp + + didFinishLaunchingTimestamp = SentryDependencyContainer.sharedInstance().dateProvider.date().addingTimeInterval(0.2) } var sut: SentryAppStartTracker { @@ -440,10 +444,12 @@ class SentryAppStartTrackerTests: NotificationCenterTestCase { XCTAssertEqual(fixture.sysctl.processStartTimestamp, appStartMeasurement.appStartTimestamp) } - XCTAssertEqual(fixture.sysctl.moduleInitializationTimestamp, appStartMeasurement.moduleInitializationTimestamp) - XCTAssertEqual(fixture.runtimeInitTimestamp, appStartMeasurement.runtimeInitTimestamp) - XCTAssertEqual(fixture.didFinishLaunchingTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) - XCTAssertEqual(preWarmed, appStartMeasurement.isPreWarmed) + expect(appStartMeasurement.moduleInitializationTimestamp) == fixture.sysctl.moduleInitializationTimestamp + expect(appStartMeasurement.runtimeInitTimestamp) == fixture.runtimeInitTimestamp + + expect(appStartMeasurement.sdkStartTimestamp) == fixture.sdkStartTimestamp + expect(appStartMeasurement.didFinishLaunchingTimestamp) == fixture.didFinishLaunchingTimestamp + expect(appStartMeasurement.isPreWarmed) == preWarmed } private func assertValidHybridStart(type: SentryAppStartType) { diff --git a/Tests/SentryTests/Protocol/TestData.swift b/Tests/SentryTests/Protocol/TestData.swift index bd7641355df..f200769ebcf 100644 --- a/Tests/SentryTests/Protocol/TestData.swift +++ b/Tests/SentryTests/Protocol/TestData.swift @@ -328,9 +328,10 @@ class TestData { let appStartDuration = 0.5 let main = appStartTimestamp.addingTimeInterval(0.15) let runtimeInit = appStartTimestamp.addingTimeInterval(0.05) - let didFinishLaunching = appStartTimestamp.addingTimeInterval(0.3) + let sdkStart = appStartTimestamp.addingTimeInterval(0.1) + let didFinishLaunching = appStartTimestamp.addingTimeInterval(0.2) - return SentryAppStartMeasurement(type: type, isPreWarmed: false, appStartTimestamp: appStartTimestamp, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: false, appStartTimestamp: appStartTimestamp, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, sdkStartTimestamp: sdkStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) diff --git a/Tests/SentryTests/SentrySDKTests.swift b/Tests/SentryTests/SentrySDKTests.swift index 37b63addf27..ed7fb639975 100644 --- a/Tests/SentryTests/SentrySDKTests.swift +++ b/Tests/SentryTests/SentrySDKTests.swift @@ -1,3 +1,4 @@ +import Nimble @testable import Sentry import SentryTestUtils import XCTest @@ -504,6 +505,23 @@ class SentrySDKTests: XCTestCase { XCTAssertEqual(1, SentrySDK.startInvocations) } + func testSDKStartTimestamp() { + let currentDateProvider = TestCurrentDateProvider() + SentryDependencyContainer.sharedInstance().dateProvider = currentDateProvider + + expect(SentrySDK.startTimestamp) == nil + + SentrySDK.start { options in + options.dsn = SentrySDKTests.dsnAsString + options.removeAllIntegrations() + } + + expect(SentrySDK.startTimestamp) == currentDateProvider.date() + + SentrySDK.close() + expect(SentrySDK.startTimestamp) == nil + } + func testIsEnabled() { XCTAssertFalse(SentrySDK.isEnabled) diff --git a/Tests/SentryTests/Transaction/SentryTracerTests.swift b/Tests/SentryTests/Transaction/SentryTracerTests.swift index 2ab9f8b2e98..b9d2dbfd456 100644 --- a/Tests/SentryTests/Transaction/SentryTracerTests.swift +++ b/Tests/SentryTests/Transaction/SentryTracerTests.swift @@ -78,13 +78,14 @@ class SentryTracerTests: XCTestCase { let runtimeInit = appStart.addingTimeInterval(runtimeInitDuration) let mainDuration = 0.15 let main = appStart.addingTimeInterval(mainDuration) - let didFinishLaunching = appStart.addingTimeInterval(0.3) + let sdkStart = appStart.addingTimeInterval(0.1) + let didFinishLaunching = appStart.addingTimeInterval(0.2) appStart = preWarmed ? main : appStart appStartDuration = preWarmed ? appStartDuration - runtimeInitDuration - mainDuration : appStartDuration appStartEnd = appStart.addingTimeInterval(appStartDuration) - return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, didFinishLaunchingTimestamp: didFinishLaunching) + return SentryAppStartMeasurement(type: type, isPreWarmed: preWarmed, appStartTimestamp: appStart, duration: appStartDuration, runtimeInitTimestamp: runtimeInit, moduleInitializationTimestamp: main, sdkStartTimestamp: sdkStart, didFinishLaunchingTimestamp: didFinishLaunching) } #endif // os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) @@ -763,6 +764,7 @@ class SentryTracerTests: XCTestCase { duration: 0.5, runtimeInitTimestamp: fixture.currentDateProvider.date(), moduleInitializationTimestamp: fixture.currentDateProvider.date(), + sdkStartTimestamp: fixture.currentDateProvider.date(), didFinishLaunchingTimestamp: fixture.currentDateProvider.date() )) @@ -1188,7 +1190,7 @@ class SentryTracerTests: XCTestCase { #if os(iOS) || os(tvOS) || targetEnvironment(macCatalyst) private func assertAppStartsSpanAdded(transaction: Transaction, startType: String, operation: String, appStartMeasurement: SentryAppStartMeasurement) { let spans: [SentrySpan]? = Dynamic(transaction).spans - XCTAssertEqual(5, spans?.count) + expect(spans?.count) == 6 let appLaunchSpan = spans?.first { span in span.spanDescription == startType @@ -1214,7 +1216,8 @@ class SentryTracerTests: XCTestCase { assertSpan("Pre Runtime Init", appStartMeasurement.appStartTimestamp, appStartMeasurement.runtimeInitTimestamp) assertSpan("Runtime Init to Pre Main Initializers", appStartMeasurement.runtimeInitTimestamp, appStartMeasurement.moduleInitializationTimestamp) - assertSpan("UIKit and Application Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) + assertSpan("UIKit Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.sdkStartTimestamp) + assertSpan("Application Init", appStartMeasurement.sdkStartTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) assertSpan("Initial Frame Render", appStartMeasurement.didFinishLaunchingTimestamp, fixture.appStartEnd) } @@ -1230,7 +1233,7 @@ class SentryTracerTests: XCTestCase { private func assertPreWarmedAppStartsSpanAdded(transaction: Transaction, startType: String, operation: String, appStartMeasurement: SentryAppStartMeasurement) { let spans: [SentrySpan]? = Dynamic(transaction).spans - XCTAssertEqual(3, spans?.count) + expect(spans?.count) == 4 let appLaunchSpan = spans?.first { span in span.spanDescription == startType @@ -1252,7 +1255,8 @@ class SentryTracerTests: XCTestCase { XCTAssertEqual(timestamp, span?.timestamp) } - assertSpan("UIKit and Application Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) + assertSpan("UIKit Init", appStartMeasurement.moduleInitializationTimestamp, appStartMeasurement.sdkStartTimestamp) + assertSpan("Application Init", appStartMeasurement.sdkStartTimestamp, appStartMeasurement.didFinishLaunchingTimestamp) assertSpan("Initial Frame Render", appStartMeasurement.didFinishLaunchingTimestamp, fixture.appStartEnd) }