From 53bfe9958d8499949cf9749d05a2aacc10e1b3aa Mon Sep 17 00:00:00 2001 From: Alexandre Costanza Date: Fri, 22 Jan 2021 20:29:08 +0100 Subject: [PATCH 1/5] RUMM-1026 Make ObjcAppLaunchHandler use sysctl and NSRunLoop to gather a more accurate App Launch Time --- .../Core/System/LaunchTimeProvider.swift | 5 +- .../_Datadog_Private/ObjcAppLaunchHandler.m | 106 ++++++++++++------ .../include/ObjcAppLaunchHandler.h | 8 +- 3 files changed, 73 insertions(+), 46 deletions(-) diff --git a/Sources/Datadog/Core/System/LaunchTimeProvider.swift b/Sources/Datadog/Core/System/LaunchTimeProvider.swift index 9eacf89594..475ae31eae 100644 --- a/Sources/Datadog/Core/System/LaunchTimeProvider.swift +++ b/Sources/Datadog/Core/System/LaunchTimeProvider.swift @@ -16,10 +16,7 @@ internal protocol LaunchTimeProviderType { internal class LaunchTimeProvider: LaunchTimeProviderType { var launchTime: TimeInterval? { - // Following dynamic dispatch synchronisation mutes TSAN issues when running tests from CLI. - objc_sync_enter(self) - let time = ObjcAppLaunchHandler.launchTime() - objc_sync_exit(self) + let time = AppLaunchTime() return time > 0 ? time : nil } } diff --git a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m index f067f0d6e3..f8a1208e65 100644 --- a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m +++ b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m @@ -4,60 +4,94 @@ * Copyright 2019-2020 Datadog, Inc. */ -#import #import "ObjcAppLaunchHandler.h" +#import +#import + +// `AppLaunchHandler` aims to track some times as part of the sequence described in Apple's "About the App Launch Sequence" +// https://developer.apple.com/documentation/uikit/app_and_environment/responding_to_the_launch_of_your_app/about_the_app_launch_sequence -@interface AppLaunchTimer : NSObject -@property NSDate *frameworkLoadTime; -// Knowing how this value is collected and that it is written only once, the use of -// `atomic` property is enough for thread safety. It guarantees that neither partial -// nor garbage value will be returned. -@property (atomic) NSTimeInterval timeToApplicationBecomeActive; +// Note that the following properties will be set early enough in the App lifecycle to avoid any race conditions without any specific synchronization means. +static NSTimeInterval TimeToApplicationFinishedLaunching = 0.0; +static NSTimeInterval TimeToLoadApplicationRootUI = 0.0; + +@interface AppLaunchHandler : NSObject @end -@implementation AppLaunchTimer +@implementation AppLaunchHandler { + NSTimeInterval _processStartTime; + NSTimeInterval _applicationMainEndTime; + NSTimeInterval _frameworkLoadTime; +} + ++ (void)load { + // This is called at the `_Datadog_Private` load time, keep the work minimal + NSTimeInterval now = CFAbsoluteTimeGetCurrent(); + // Schedule a call for the first turn of run loop before the main nib/storyboard is loaded: + [NSRunLoop.mainRunLoop performInModes:@[NSRunLoopCommonModes] block:^{ + AppLaunchHandler *handler = [[self alloc] initWithFrameworkLoadTime:now]; + [handler markEndOfUIApplicationMain]; + [handler scheduleUIApplicationDidFinishLaunchingMarking]; + }]; +} -- (instancetype)init +- (instancetype)initWithFrameworkLoadTime:(NSTimeInterval)frameworkLoadTime { - self = [super init]; - if (self) { - NSDate *time = [NSDate new]; - self.frameworkLoadTime = time; - self.timeToApplicationBecomeActive = -1; - [[NSNotificationCenter defaultCenter] addObserver:self - selector:@selector(handleDidBecomeActiveNotification) - name:UIApplicationDidBecomeActiveNotification - object:nil - ]; + if (self = [super init]) { + _frameworkLoadTime = frameworkLoadTime; } return self; } -- (void)handleDidBecomeActiveNotification { - if (self.timeToApplicationBecomeActive > -1) { // sanity check & extra safety - return; - } +- (void)markEndOfUIApplicationMain { + _applicationMainEndTime = CFAbsoluteTimeGetCurrent(); +} - NSDate *time = [NSDate new]; - NSTimeInterval duration = [time timeIntervalSinceDate:self.frameworkLoadTime]; - self.timeToApplicationBecomeActive = duration; - [[NSNotificationCenter defaultCenter] removeObserver:self]; +- (void)scheduleUIApplicationDidFinishLaunchingMarking { + id __block token = [NSNotificationCenter.defaultCenter + addObserverForName:UIApplicationDidFinishLaunchingNotification + object:nil + queue:NSOperationQueue.mainQueue + usingBlock:^(NSNotification *_){ + [self markUIApplicationDidFinishLaunching]; + [NSNotificationCenter.defaultCenter removeObserver:token]; + }]; } -@end +- (void)markUIApplicationDidFinishLaunching { + NSTimeInterval now = CFAbsoluteTimeGetCurrent(); + [self queryProcessStartTime]; -@implementation ObjcAppLaunchHandler: NSObject + TimeToApplicationFinishedLaunching = now - _processStartTime; + TimeToLoadApplicationRootUI = now - _applicationMainEndTime; +} -static AppLaunchTimer *_timer; +- (void)queryProcessStartTime { + // Query the current process' start time: + // https://www.freebsd.org/cgi/man.cgi?sysctl(3) + // https://github.com/darwin-on-arm/xnu/blob/707bfdc4e9a46e3612e53994fffc64542d3f7e72/bsd/sys/sysctl.h#L681 + // https://github.com/darwin-on-arm/xnu/blob/707bfdc4e9a46e3612e53994fffc64542d3f7e72/bsd/sys/proc.h#L97 -+ (void)load { - // This is called at the `_Datadog_Private` load time, keep the work minimal - _timer = [AppLaunchTimer new]; -} + struct kinfo_proc kip; + size_t kipSize = sizeof(kip); + int mib[4] = {CTL_KERN, KERN_PROC, KERN_PROC_PID, getpid()}; + int res = sysctl(mib, 4, &kip, &kipSize, NULL, 0); -+ (NSTimeInterval)launchTime { - return _timer.timeToApplicationBecomeActive; + if (res == 0) { + // The process' start time is provided relative to 1 Jan 1970 + struct timeval startTime = kip.kp_proc.p_starttime; + _processStartTime = startTime.tv_sec + startTime.tv_usec / USEC_PER_SEC; + // Convert to time since 1 Jan 2001 to align with CFAbsoluteTimeGetCurrent() + _processStartTime -= kCFAbsoluteTimeIntervalSince1970; + } else { + // Fallback to less accurate delta with DD's framework load time + _processStartTime = _frameworkLoadTime; + } } @end + +CFTimeInterval AppLaunchTime() { + return TimeToApplicationFinishedLaunching; +} diff --git a/Sources/_Datadog_Private/include/ObjcAppLaunchHandler.h b/Sources/_Datadog_Private/include/ObjcAppLaunchHandler.h index 26a5d20951..4de259cecf 100644 --- a/Sources/_Datadog_Private/include/ObjcAppLaunchHandler.h +++ b/Sources/_Datadog_Private/include/ObjcAppLaunchHandler.h @@ -4,10 +4,6 @@ * Copyright 2019-2020 Datadog, Inc. */ -#import +#import -@interface ObjcAppLaunchHandler : NSObject - -+ (NSTimeInterval)launchTime; - -@end +CFTimeInterval AppLaunchTime(void); From 636a9d07dba0b28d3e72ff1702035d3eff909abe Mon Sep 17 00:00:00 2001 From: Alexandre Costanza Date: Tue, 26 Jan 2021 15:04:40 +0100 Subject: [PATCH 2/5] RUMM-1026 Address CR feedback and clean up unused things --- .../_Datadog_Private/ObjcAppLaunchHandler.m | 39 +++++++------------ 1 file changed, 14 insertions(+), 25 deletions(-) diff --git a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m index f8a1208e65..7a272fc31c 100644 --- a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m +++ b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m @@ -11,60 +11,49 @@ // `AppLaunchHandler` aims to track some times as part of the sequence described in Apple's "About the App Launch Sequence" // https://developer.apple.com/documentation/uikit/app_and_environment/responding_to_the_launch_of_your_app/about_the_app_launch_sequence -// Note that the following properties will be set early enough in the App lifecycle to avoid any race conditions without any specific synchronization means. -static NSTimeInterval TimeToApplicationFinishedLaunching = 0.0; -static NSTimeInterval TimeToLoadApplicationRootUI = 0.0; +// Note that the following property will be set early enough in the App lifecycle to avoid any race conditions without any specific synchronization means. +static NSTimeInterval TimeToApplicationDidBecomeActive = 0.0; @interface AppLaunchHandler : NSObject @end @implementation AppLaunchHandler { NSTimeInterval _processStartTime; - NSTimeInterval _applicationMainEndTime; NSTimeInterval _frameworkLoadTime; } + (void)load { // This is called at the `_Datadog_Private` load time, keep the work minimal - NSTimeInterval now = CFAbsoluteTimeGetCurrent(); - // Schedule a call for the first turn of run loop before the main nib/storyboard is loaded: - [NSRunLoop.mainRunLoop performInModes:@[NSRunLoopCommonModes] block:^{ - AppLaunchHandler *handler = [[self alloc] initWithFrameworkLoadTime:now]; - [handler markEndOfUIApplicationMain]; - [handler scheduleUIApplicationDidFinishLaunchingMarking]; - }]; + [[self new] scheduleUIApplicationDidFinishLaunchingMarking]; } -- (instancetype)initWithFrameworkLoadTime:(NSTimeInterval)frameworkLoadTime +- (instancetype)init { if (self = [super init]) { - _frameworkLoadTime = frameworkLoadTime; + _frameworkLoadTime = CFAbsoluteTimeGetCurrent(); } return self; } -- (void)markEndOfUIApplicationMain { - _applicationMainEndTime = CFAbsoluteTimeGetCurrent(); -} - - (void)scheduleUIApplicationDidFinishLaunchingMarking { id __block token = [NSNotificationCenter.defaultCenter - addObserverForName:UIApplicationDidFinishLaunchingNotification + addObserverForName:UIApplicationDidBecomeActiveNotification object:nil queue:NSOperationQueue.mainQueue usingBlock:^(NSNotification *_){ - [self markUIApplicationDidFinishLaunching]; + [self markUIApplicationDidBecomeActive]; [NSNotificationCenter.defaultCenter removeObserver:token]; }]; } -- (void)markUIApplicationDidFinishLaunching { - NSTimeInterval now = CFAbsoluteTimeGetCurrent(); +- (void)markUIApplicationDidBecomeActive { + if (TimeToApplicationDidBecomeActive > 0) { + return; + } + NSTimeInterval now = CFAbsoluteTimeGetCurrent(); [self queryProcessStartTime]; - - TimeToApplicationFinishedLaunching = now - _processStartTime; - TimeToLoadApplicationRootUI = now - _applicationMainEndTime; + TimeToApplicationDidBecomeActive = now - _processStartTime; } - (void)queryProcessStartTime { @@ -93,5 +82,5 @@ - (void)queryProcessStartTime { @end CFTimeInterval AppLaunchTime() { - return TimeToApplicationFinishedLaunching; + return TimeToApplicationDidBecomeActive; } From 9de2d74258fea23da87ea4967c3bbff3cf5854dd Mon Sep 17 00:00:00 2001 From: Alexandre Costanza Date: Tue, 26 Jan 2021 16:20:43 +0100 Subject: [PATCH 3/5] RUMM-1026 Address CR and replace object instantiation by simple function calls --- .../_Datadog_Private/ObjcAppLaunchHandler.m | 80 ++++++++----------- 1 file changed, 34 insertions(+), 46 deletions(-) diff --git a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m index 7a272fc31c..4b32982732 100644 --- a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m +++ b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m @@ -14,49 +14,8 @@ // Note that the following property will be set early enough in the App lifecycle to avoid any race conditions without any specific synchronization means. static NSTimeInterval TimeToApplicationDidBecomeActive = 0.0; -@interface AppLaunchHandler : NSObject -@end - -@implementation AppLaunchHandler { - NSTimeInterval _processStartTime; - NSTimeInterval _frameworkLoadTime; -} - -+ (void)load { - // This is called at the `_Datadog_Private` load time, keep the work minimal - [[self new] scheduleUIApplicationDidFinishLaunchingMarking]; -} - -- (instancetype)init -{ - if (self = [super init]) { - _frameworkLoadTime = CFAbsoluteTimeGetCurrent(); - } - return self; -} - -- (void)scheduleUIApplicationDidFinishLaunchingMarking { - id __block token = [NSNotificationCenter.defaultCenter - addObserverForName:UIApplicationDidBecomeActiveNotification - object:nil - queue:NSOperationQueue.mainQueue - usingBlock:^(NSNotification *_){ - [self markUIApplicationDidBecomeActive]; - [NSNotificationCenter.defaultCenter removeObserver:token]; - }]; -} - -- (void)markUIApplicationDidBecomeActive { - if (TimeToApplicationDidBecomeActive > 0) { - return; - } - - NSTimeInterval now = CFAbsoluteTimeGetCurrent(); - [self queryProcessStartTime]; - TimeToApplicationDidBecomeActive = now - _processStartTime; -} - -- (void)queryProcessStartTime { +NS_INLINE NSTimeInterval QueryProcessStartTimeWithFallback(NSTimeInterval fallbackTime) { + NSTimeInterval processStartTime; // Query the current process' start time: // https://www.freebsd.org/cgi/man.cgi?sysctl(3) // https://github.com/darwin-on-arm/xnu/blob/707bfdc4e9a46e3612e53994fffc64542d3f7e72/bsd/sys/sysctl.h#L681 @@ -70,13 +29,42 @@ - (void)queryProcessStartTime { if (res == 0) { // The process' start time is provided relative to 1 Jan 1970 struct timeval startTime = kip.kp_proc.p_starttime; - _processStartTime = startTime.tv_sec + startTime.tv_usec / USEC_PER_SEC; + processStartTime = startTime.tv_sec + startTime.tv_usec / USEC_PER_SEC; // Convert to time since 1 Jan 2001 to align with CFAbsoluteTimeGetCurrent() - _processStartTime -= kCFAbsoluteTimeIntervalSince1970; + processStartTime -= kCFAbsoluteTimeIntervalSince1970; } else { // Fallback to less accurate delta with DD's framework load time - _processStartTime = _frameworkLoadTime; + processStartTime = fallbackTime; } + return processStartTime; +} + +NS_INLINE void ComputeTimeToApplicationDidBecomeActiveWithFallback(NSTimeInterval fallbackTime) { + if (TimeToApplicationDidBecomeActive > 0) { + return; + } + + NSTimeInterval now = CFAbsoluteTimeGetCurrent(); + NSTimeInterval processStartTime = QueryProcessStartTimeWithFallback(fallbackTime); + TimeToApplicationDidBecomeActive = now - processStartTime; +} + +@interface AppLaunchHandler : NSObject +@end + +@implementation AppLaunchHandler + ++ (void)load { + // This is called at the `_Datadog_Private` load time, keep the work minimal + NSTimeInterval frameworkLoadTime = CFAbsoluteTimeGetCurrent(); + id __block token = [NSNotificationCenter.defaultCenter + addObserverForName:UIApplicationDidBecomeActiveNotification + object:nil + queue:NSOperationQueue.mainQueue + usingBlock:^(NSNotification *_){ + ComputeTimeToApplicationDidBecomeActiveWithFallback(frameworkLoadTime); + [NSNotificationCenter.defaultCenter removeObserver:token]; + }]; } @end From 09d6d5d63051479cb9d965a9f8fda9f52c5e3fde Mon Sep 17 00:00:00 2001 From: Alexandre Costanza Date: Thu, 28 Jan 2021 11:44:56 +0100 Subject: [PATCH 4/5] RUMM-1026 Add a read-write lock to ensure thread safety around TimeToApplicationDidBecomeActive --- Sources/_Datadog_Private/ObjcAppLaunchHandler.m | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m index 4b32982732..dcd660f076 100644 --- a/Sources/_Datadog_Private/ObjcAppLaunchHandler.m +++ b/Sources/_Datadog_Private/ObjcAppLaunchHandler.m @@ -7,11 +7,13 @@ #import "ObjcAppLaunchHandler.h" #import #import +#import // `AppLaunchHandler` aims to track some times as part of the sequence described in Apple's "About the App Launch Sequence" // https://developer.apple.com/documentation/uikit/app_and_environment/responding_to_the_launch_of_your_app/about_the_app_launch_sequence -// Note that the following property will be set early enough in the App lifecycle to avoid any race conditions without any specific synchronization means. +// A Read-Write lock to allow concurrent reads of TimeToApplicationDidBecomeActive, unless the initial (and only) write is locking it. +static pthread_rwlock_t rwLock; static NSTimeInterval TimeToApplicationDidBecomeActive = 0.0; NS_INLINE NSTimeInterval QueryProcessStartTimeWithFallback(NSTimeInterval fallbackTime) { @@ -62,7 +64,12 @@ + (void)load { object:nil queue:NSOperationQueue.mainQueue usingBlock:^(NSNotification *_){ + + pthread_rwlock_init(&rwLock, NULL); + pthread_rwlock_wrlock(&rwLock); ComputeTimeToApplicationDidBecomeActiveWithFallback(frameworkLoadTime); + pthread_rwlock_unlock(&rwLock); + [NSNotificationCenter.defaultCenter removeObserver:token]; }]; } @@ -70,5 +77,8 @@ + (void)load { @end CFTimeInterval AppLaunchTime() { - return TimeToApplicationDidBecomeActive; + pthread_rwlock_rdlock(&rwLock); + CFTimeInterval time = TimeToApplicationDidBecomeActive; + pthread_rwlock_unlock(&rwLock); + return time; } From 2e87e86cd92e607975fc1d4b0981feac4fba9498 Mon Sep 17 00:00:00 2001 From: Alexandre Costanza Date: Thu, 28 Jan 2021 14:02:24 +0100 Subject: [PATCH 5/5] RUMM-1026 Add back the @synchronized inside LaunchTimeProvider to help with TSAN --- Sources/Datadog/Core/System/LaunchTimeProvider.swift | 3 +++ 1 file changed, 3 insertions(+) diff --git a/Sources/Datadog/Core/System/LaunchTimeProvider.swift b/Sources/Datadog/Core/System/LaunchTimeProvider.swift index 475ae31eae..ad36a16338 100644 --- a/Sources/Datadog/Core/System/LaunchTimeProvider.swift +++ b/Sources/Datadog/Core/System/LaunchTimeProvider.swift @@ -16,7 +16,10 @@ internal protocol LaunchTimeProviderType { internal class LaunchTimeProvider: LaunchTimeProviderType { var launchTime: TimeInterval? { + // Even if AppLaunchTime() is using a lock behind the scenes, TSAN will report a data race if there are no synchronizations at this level. + objc_sync_enter(self) let time = AppLaunchTime() + objc_sync_exit(self) return time > 0 ? time : nil } }