diff --git a/React/Base/RCTBatchedBridge.m b/React/Base/RCTBatchedBridge.m index 9547262cb926cf..c85011c556f86b 100644 --- a/React/Base/RCTBatchedBridge.m +++ b/React/Base/RCTBatchedBridge.m @@ -131,7 +131,9 @@ - (void)start // Asynchronously initialize the JS executor dispatch_group_async(setupJSExecutorAndModuleConfig, bridgeQueue, ^{ + RCTPerformanceLoggerStart(RCTPLJSCExecutorSetup); [weakSelf setUpExecutor]; + RCTPerformanceLoggerEnd(RCTPLJSCExecutorSetup); }); // Asynchronously gather the module config @@ -171,13 +173,8 @@ - (void)start - (void)loadSource:(RCTSourceLoadBlock)_onSourceLoad { RCTPerformanceLoggerStart(RCTPLScriptDownload); - NSUInteger cookie = RCTProfileBeginAsyncEvent(0, @"JavaScript download", nil); - - // Suppress a warning if RCTProfileBeginAsyncEvent gets compiled out - (void)cookie; RCTSourceLoadBlock onSourceLoad = ^(NSError *error, NSData *source) { - RCTProfileEndAsyncEvent(0, @"native", cookie, @"JavaScript download", @"JS async", nil); RCTPerformanceLoggerEnd(RCTPLScriptDownload); _onSourceLoad(error, source); @@ -332,7 +329,7 @@ - (void)initModulesWithDispatchGroup:(dispatch_group_t)dispatchGroup moduleClass, moduleName, moduleData.moduleClass); } } - + // Instantiate moduleData (TODO: can we defer this until config generation?) moduleData = [[RCTModuleData alloc] initWithModuleClass:moduleClass bridge:self]; @@ -366,6 +363,7 @@ - (void)initModulesWithDispatchGroup:(dispatch_group_t)dispatchGroup _moduleSetupComplete = YES; // Set up modules that require main thread init or constants export + RCTPerformanceLoggerSet(RCTPLNativeModuleMainThread, 0); for (RCTModuleData *moduleData in _moduleDataByID) { __weak RCTBatchedBridge *weakSelf = self; if (moduleData.requiresMainThreadSetup) { @@ -376,8 +374,10 @@ - (void)initModulesWithDispatchGroup:(dispatch_group_t)dispatchGroup // they will already be available before they are ever required. dispatch_group_async(dispatchGroup, dispatch_get_main_queue(), ^{ if (weakSelf.valid) { + RCTPerformanceLoggerAppendStart(RCTPLNativeModuleMainThread); (void)[moduleData instance]; [moduleData gatherConstants]; + RCTPerformanceLoggerAppendEnd(RCTPLNativeModuleMainThread); } }); } else if (moduleData.hasConstantsToExport) { @@ -386,7 +386,9 @@ - (void)initModulesWithDispatchGroup:(dispatch_group_t)dispatchGroup (void)[moduleData instance]; dispatch_group_async(dispatchGroup, dispatch_get_main_queue(), ^{ if (weakSelf.valid) { + RCTPerformanceLoggerAppendStart(RCTPLNativeModuleMainThread); [moduleData gatherConstants]; + RCTPerformanceLoggerAppendEnd(RCTPLNativeModuleMainThread); } }); } diff --git a/React/Base/RCTModuleData.m b/React/Base/RCTModuleData.m index bf2f7f8461306c..d29441b40f112d 100644 --- a/React/Base/RCTModuleData.m +++ b/React/Base/RCTModuleData.m @@ -13,6 +13,7 @@ #import "RCTBridge+Private.h" #import "RCTModuleMethod.h" #import "RCTLog.h" +#import "RCTProfile.h" #import "RCTUtils.h" @implementation RCTModuleData @@ -185,6 +186,7 @@ - (BOOL)hasInstance - (id)instance { if (!_setupComplete) { + RCT_PROFILE_BEGIN_EVENT(0, [NSString stringWithFormat:@"[RCTModuleData instanceForClass:%@]", _moduleClass], nil); if (_requiresMainThreadSetup) { // The chances of deadlock here are low, because module init very rarely // calls out to other threads, however we can't control when a module might @@ -196,6 +198,7 @@ - (BOOL)hasInstance } else { [self setUpInstanceAndBridge]; } + RCT_PROFILE_END_EVENT(0, @"", nil); } return _instance; } diff --git a/React/Base/RCTPerformanceLogger.h b/React/Base/RCTPerformanceLogger.h index d26a37687dbf5d..c8978071cff881 100644 --- a/React/Base/RCTPerformanceLogger.h +++ b/React/Base/RCTPerformanceLogger.h @@ -15,15 +15,48 @@ typedef NS_ENUM(NSUInteger, RCTPLTag) { RCTPLScriptDownload = 0, RCTPLScriptExecution, RCTPLNativeModuleInit, + RCTPLNativeModuleMainThread, RCTPLNativeModulePrepareConfig, RCTPLNativeModuleInjectConfig, + RCTPLJSCExecutorSetup, RCTPLTTI, RCTPLBundleSize, RCTPLSize }; +/** + * Starts measuring a metric with the given tag. + * Overrides previous value if the measurement has been already started. + * If RCTProfile is enabled it also begins appropriate async event. + */ RCT_EXTERN void RCTPerformanceLoggerStart(RCTPLTag tag); + +/** + * Stops measuring a metric with given tag. + * Checks if RCTPerformanceLoggerStart() has been called before + * and doesn't do anything and log a message if it hasn't. + * If RCTProfile is enabled it also ends appropriate async event. + */ RCT_EXTERN void RCTPerformanceLoggerEnd(RCTPLTag tag); + +/** + * Sets given value for a metric with given tag. + */ RCT_EXTERN void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value); + +/** + * Starts an additional measurement for a metric with given tag. + * It doesn't override previous measurement, instead it'll append a new value + * to the old one. + */ +RCT_EXTERN void RCTPerformanceLoggerAppendStart(RCTPLTag tag); + +/** + * Stops measurement and appends the result to the metric with given tag. + * Checks if RCTPerformanceLoggerAppendStart() has been called before + * and doesn't do anything and log a message if it hasn't. + */ +RCT_EXTERN void RCTPerformanceLoggerAppendEnd(RCTPLTag tag); + RCT_EXTERN NSArray *RCTPerformanceLoggerOutput(void); RCT_EXTERN NSArray *RCTPerformanceLoggerLabels(void); diff --git a/React/Base/RCTPerformanceLogger.m b/React/Base/RCTPerformanceLogger.m index d7f45d6930c472..7bca4a728c680d 100644 --- a/React/Base/RCTPerformanceLogger.m +++ b/React/Base/RCTPerformanceLogger.m @@ -12,11 +12,18 @@ #import "RCTPerformanceLogger.h" #import "RCTRootView.h" #import "RCTLog.h" +#import "RCTProfile.h" static int64_t RCTPLData[RCTPLSize][2] = {}; +static int64_t RCTPLCookies[RCTPLSize] = {}; void RCTPerformanceLoggerStart(RCTPLTag tag) { + if (RCTProfileIsProfiling()) { + NSString *label = RCTPerformanceLoggerLabels()[tag]; + RCTPLCookies[tag] = RCTProfileBeginAsyncEvent(0, label, nil); + } + RCTPLData[tag][0] = CACurrentMediaTime() * 1000; RCTPLData[tag][1] = 0; } @@ -25,6 +32,11 @@ void RCTPerformanceLoggerEnd(RCTPLTag tag) { if (RCTPLData[tag][0] != 0 && RCTPLData[tag][1] == 0) { RCTPLData[tag][1] = CACurrentMediaTime() * 1000; + + if (RCTProfileIsProfiling()) { + NSString *label = RCTPerformanceLoggerLabels()[tag]; + RCTProfileEndAsyncEvent(0, @"native", RCTPLCookies[tag], label, @"RCTPerformanceLogger", nil); + } } else { RCTLogInfo(@"Unbalanced calls start/end for tag %li", (unsigned long)tag); } @@ -36,6 +48,21 @@ void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value) RCTPLData[tag][1] = value; } +void RCTPerformanceLoggerAppendStart(RCTPLTag tag) +{ + RCTPLData[tag][0] = CACurrentMediaTime() * 1000; +} + +void RCTPerformanceLoggerAppendEnd(RCTPLTag tag) +{ + if (RCTPLData[tag][0] != 0) { + RCTPLData[tag][1] += CACurrentMediaTime() * 1000 - RCTPLData[tag][0]; + RCTPLData[tag][0] = 0; + } else { + RCTLogInfo(@"Unbalanced calls start/end for tag %li", (unsigned long)tag); + } +} + NSArray *RCTPerformanceLoggerOutput(void) { return @[ @@ -45,10 +72,14 @@ void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value) @(RCTPLData[RCTPLScriptExecution][1]), @(RCTPLData[RCTPLNativeModuleInit][0]), @(RCTPLData[RCTPLNativeModuleInit][1]), + @(RCTPLData[RCTPLNativeModuleMainThread][0]), + @(RCTPLData[RCTPLNativeModuleMainThread][1]), @(RCTPLData[RCTPLNativeModulePrepareConfig][0]), @(RCTPLData[RCTPLNativeModulePrepareConfig][1]), @(RCTPLData[RCTPLNativeModuleInjectConfig][0]), @(RCTPLData[RCTPLNativeModuleInjectConfig][1]), + @(RCTPLData[RCTPLJSCExecutorSetup][0]), + @(RCTPLData[RCTPLJSCExecutorSetup][1]), @(RCTPLData[RCTPLTTI][0]), @(RCTPLData[RCTPLTTI][1]), @(RCTPLData[RCTPLBundleSize][0]), @@ -58,15 +89,22 @@ void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value) NSArray *RCTPerformanceLoggerLabels(void) { - return @[ - @"ScriptDownload", - @"ScriptExecution", - @"NativeModuleInit", - @"NativeModulePrepareConfig", - @"NativeModuleInjectConfig", - @"TTI", - @"BundleSize", - ]; + static NSArray *labels; + static dispatch_once_t token; + dispatch_once(&token, ^{ + labels = @[ + @"ScriptDownload", + @"ScriptExecution", + @"NativeModuleInit", + @"NativeModuleMainThread", + @"NativeModulePrepareConfig", + @"NativeModuleInjectConfig", + @"JSCExecutorSetup", + @"RootViewTTI", + @"BundleSize", + ]; + }); + return labels; } @interface RCTPerformanceLogger : NSObject