From 0c7480442778e98da3800a400345a620dde4ea5b Mon Sep 17 00:00:00 2001 From: Tadeu Zagallo Date: Wed, 4 Nov 2015 09:00:01 -0800 Subject: [PATCH] Use dispatch_async instead of lock Summary: public The initial implementation used a lock to manage the stored profile information, blocking the caller thread for longer than it should. Replace it with a private queue, since the only thing we need to from the caller is to record the immediate call time and the caller thread/queue, all the rest has absolutely no priority. Use macros to also defer work done when generate the name of the events. Reviewed By: nicklockwood Differential Revision: D2603120 fb-gh-sync-id: e3e36160c893e7ae9ed3558f07c854ea76396661 --- React/Base/RCTBatchedBridge.m | 7 +- React/Profiler/RCTProfile.h | 40 ++++++-- React/Profiler/RCTProfile.m | 177 ++++++++++++++++++++-------------- 3 files changed, 140 insertions(+), 84 deletions(-) diff --git a/React/Base/RCTBatchedBridge.m b/React/Base/RCTBatchedBridge.m index da7f33e14..edf436e10 100644 --- a/React/Base/RCTBatchedBridge.m +++ b/React/Base/RCTBatchedBridge.m @@ -868,9 +868,10 @@ RCT_NOT_IMPLEMENTED(- (instancetype)initWithBundleURL:(__unused NSURL *)bundleUR RCTAssertMainThread(); [_javaScriptExecutor executeBlockOnJavaScriptQueue:^{ - NSString *log = RCTProfileEnd(self); - NSData *logData = [log dataUsingEncoding:NSUTF8StringEncoding]; - callback(logData); + RCTProfileEnd(self, ^(NSString *log) { + NSData *logData = [log dataUsingEncoding:NSUTF8StringEncoding]; + callback(logData); + }); }]; } diff --git a/React/Profiler/RCTProfile.h b/React/Profiler/RCTProfile.h index c184cae18..31c1c56db 100644 --- a/React/Profiler/RCTProfile.h +++ b/React/Profiler/RCTProfile.h @@ -36,6 +36,8 @@ _Pragma("clang diagnostic pop") #define RCTProfileEndFlowEvent() \ _RCTProfileEndFlowEvent(__rct_profile_flow_id) +RCT_EXTERN dispatch_queue_t RCTProfileGetQueue(void); + RCT_EXTERN NSNumber *_RCTProfileBeginFlowEvent(void); RCT_EXTERN void _RCTProfileEndFlowEvent(NSNumber *); @@ -54,23 +56,44 @@ RCT_EXTERN void RCTProfileInit(RCTBridge *); * returned is compliant with google's trace event format - the format used * as input to trace-viewer */ -RCT_EXTERN NSString *RCTProfileEnd(RCTBridge *); +RCT_EXTERN void RCTProfileEnd(RCTBridge *, void (^)(NSString *)); /** * Collects the initial event information for the event and returns a reference ID */ -RCT_EXTERN void RCTProfileBeginEvent(uint64_t tag, - NSString *name, - NSDictionary *args); +RCT_EXTERN void _RCTProfileBeginEvent(NSThread *calleeThread, + NSTimeInterval time, + uint64_t tag, + NSString *name, + NSDictionary *args); +#define RCTProfileBeginEvent(...) { \ + NSThread *calleeThread = [NSThread currentThread]; \ + NSTimeInterval time = CACurrentMediaTime(); \ + dispatch_async(RCTProfileGetQueue(), ^{ \ + _RCTProfileBeginEvent(calleeThread, time, __VA_ARGS__); \ + }); \ +} /** * The ID returned by BeginEvent should then be passed into EndEvent, with the * rest of the event information. Just at this point the event will actually be * registered */ -RCT_EXTERN void RCTProfileEndEvent(uint64_t tag, - NSString *category, - NSDictionary *args); +RCT_EXTERN void _RCTProfileEndEvent(NSThread *calleeThread, + NSString *threadName, + NSTimeInterval time, + uint64_t tag, + NSString *category, + NSDictionary *args); + +#define RCTProfileEndEvent(...) { \ + NSThread *calleeThread = [NSThread currentThread]; \ + NSString *threadName = RCTCurrentThreadName(); \ + NSTimeInterval time = CACurrentMediaTime(); \ + dispatch_async(RCTProfileGetQueue(), ^{ \ + _RCTProfileEndEvent(calleeThread, threadName, time, __VA_ARGS__); \ + }); \ +} /** * Collects the initial event information for the event and returns a reference ID @@ -89,6 +112,7 @@ RCT_EXTERN void RCTProfileEndAsyncEvent(uint64_t tag, int cookie, NSString *name, NSDictionary *args); + /** * An event that doesn't have a duration (i.e. Notification, VSync, etc) */ @@ -123,7 +147,7 @@ RCT_EXTERN void RCTProfileUnhookModules(RCTBridge *); * Send systrace or cpu profiling information to the packager * to present to the user */ -RCT_EXTERN void RCTProfileSendResult(RCTBridge *bridge, NSString *route, NSData *profielData); +RCT_EXTERN void RCTProfileSendResult(RCTBridge *bridge, NSString *route, NSData *profileData); /** * Systrace gluecode diff --git a/React/Profiler/RCTProfile.m b/React/Profiler/RCTProfile.m index 38678d8c7..aa1940936 100644 --- a/React/Profiler/RCTProfile.m +++ b/React/Profiler/RCTProfile.m @@ -11,6 +11,7 @@ #import +#import #import #import #import @@ -37,7 +38,7 @@ NSString *const RCTProfilePrefix = @"rct_profile_"; #pragma mark - Variables -static BOOL RCTProfileProfiling; +static volatile uint32_t RCTProfileProfiling; static NSDictionary *RCTProfileInfo; static NSMutableDictionary *RCTProfileOngoingEvents; static NSTimeInterval RCTProfileStartTime; @@ -48,7 +49,6 @@ static NSUInteger RCTProfileEventID = 0; #define RCTProfileAddEvent(type, props...) \ [RCTProfileInfo[type] addObject:@{ \ @"pid": @([[NSProcessInfo processInfo] processIdentifier]), \ - @"tid": RCTCurrentThreadName(), \ props \ }]; @@ -57,11 +57,6 @@ if (!RCTProfileIsProfiling()) { \ return __VA_ARGS__; \ } -#define RCTProfileLock(...) \ -[_RCTProfileLock() lock]; \ -__VA_ARGS__ \ -[_RCTProfileLock() unlock] - #pragma mark - systrace glue code static RCTProfileCallbacks *callbacks; @@ -95,18 +90,6 @@ void RCTProfileRegisterCallbacks(RCTProfileCallbacks *cb) #pragma mark - Private Helpers -static NSLock *_RCTProfileLock() -{ - static dispatch_once_t token; - static NSLock *lock; - dispatch_once(&token, ^{ - lock = [NSLock new]; - lock.name = @"RCTProfileLock"; - }); - - return lock; -} - static NSNumber *RCTProfileTimestamp(NSTimeInterval timestamp) { return @((timestamp - RCTProfileStartTime) * 1e6); @@ -276,109 +259,136 @@ void RCTProfileUnhookModules(RCTBridge *bridge) #pragma mark - Public Functions +dispatch_queue_t RCTProfileGetQueue(void) +{ + static dispatch_queue_t queue; + static dispatch_once_t onceToken; + dispatch_once(&onceToken, ^{ + queue = dispatch_queue_create("com.facebook.react.Profiler", DISPATCH_QUEUE_SERIAL); + }); + return queue; +} + BOOL RCTProfileIsProfiling(void) { - return RCTProfileProfiling; + return (BOOL)OSAtomicAnd32(1, &RCTProfileProfiling); } void RCTProfileInit(RCTBridge *bridge) { - RCTProfileHookModules(bridge); - RCTProfileProfiling = YES; + // TODO: enable assert JS thread from any file (and assert here) + + OSAtomicOr32(1, &RCTProfileProfiling); if (callbacks != NULL) { size_t buffer_size = 1 << 22; systrace_buffer = calloc(1, buffer_size); callbacks->start(~((uint64_t)0), systrace_buffer, buffer_size); } else { - RCTProfileLock( - RCTProfileStartTime = CACurrentMediaTime(); + NSTimeInterval time = CACurrentMediaTime(); + dispatch_async(RCTProfileGetQueue(), ^{ + RCTProfileStartTime = time; RCTProfileOngoingEvents = [NSMutableDictionary new]; RCTProfileInfo = @{ RCTProfileTraceEvents: [NSMutableArray new], RCTProfileSamples: [NSMutableArray new], }; - ); + }); } + RCTProfileHookModules(bridge); + [[NSNotificationCenter defaultCenter] postNotificationName:RCTProfileDidStartProfiling object:nil]; } -NSString *RCTProfileEnd(RCTBridge *bridge) +void RCTProfileEnd(RCTBridge *bridge, void (^callback)(NSString *)) { + // assert JavaScript thread here again + if (!RCTProfileIsProfiling()) { - return nil; + return; } + OSAtomicAnd32(0, &RCTProfileProfiling); + [[NSNotificationCenter defaultCenter] postNotificationName:RCTProfileDidEndProfiling object:nil]; - RCTProfileProfiling = NO; - - RCTProfileLock( - RCTProfileUnhookModules(bridge); - ); + RCTProfileUnhookModules(bridge); if (callbacks != NULL) { callbacks->stop(); - return @(systrace_buffer); + callback(@(systrace_buffer)); } else { - RCTProfileLock( + dispatch_async(RCTProfileGetQueue(), ^{ NSString *log = RCTJSONStringify(RCTProfileInfo, NULL); RCTProfileEventID = 0; RCTProfileInfo = nil; RCTProfileOngoingEvents = nil; - ); - return log; + callback(log); + }); } } -static NSMutableArray *RCTProfileGetThreadEvents(void) +static NSMutableArray *RCTProfileGetThreadEvents(NSThread *thread) { static NSString *const RCTProfileThreadEventsKey = @"RCTProfileThreadEventsKey"; NSMutableArray *threadEvents = - [NSThread currentThread].threadDictionary[RCTProfileThreadEventsKey]; + thread.threadDictionary[RCTProfileThreadEventsKey]; if (!threadEvents) { threadEvents = [NSMutableArray new]; - [NSThread currentThread].threadDictionary[RCTProfileThreadEventsKey] = threadEvents; + thread.threadDictionary[RCTProfileThreadEventsKey] = threadEvents; } return threadEvents; } -void RCTProfileBeginEvent(uint64_t tag, NSString *name, NSDictionary *args) -{ +void _RCTProfileBeginEvent( + NSThread *calleeThread, + NSTimeInterval time, + uint64_t tag, + NSString *name, + NSDictionary *args +) { + CHECK(); + RCTAssertThread(RCTProfileGetQueue(), @"Must be called RCTProfile queue");; + if (callbacks != NULL) { callbacks->begin_section(tag, name.UTF8String, args.count, RCTProfileSystraceArgsFromNSDictionary(args)); return; } - NSMutableArray *events = RCTProfileGetThreadEvents(); + NSMutableArray *events = RCTProfileGetThreadEvents(calleeThread); [events addObject:@[ - RCTProfileTimestamp(CACurrentMediaTime()), + RCTProfileTimestamp(time), @(tag), name, RCTNullIfNil(args), ]]; } -void RCTProfileEndEvent( +void _RCTProfileEndEvent( + NSThread *calleeThread, + NSString *threadName, + NSTimeInterval time, uint64_t tag, NSString *category, NSDictionary *args ) { CHECK(); + RCTAssertThread(RCTProfileGetQueue(), @"Must be called RCTProfile queue");; + if (callbacks != NULL) { callbacks->end_section(tag, args.count, RCTProfileSystraceArgsFromNSDictionary(args)); return; } - NSMutableArray *events = RCTProfileGetThreadEvents(); + NSMutableArray *events = RCTProfileGetThreadEvents(calleeThread); NSArray *event = events.lastObject; [events removeLastObject]; @@ -388,15 +398,14 @@ void RCTProfileEndEvent( NSNumber *start = event[0]; - RCTProfileLock( - RCTProfileAddEvent(RCTProfileTraceEvents, - @"name": event[2], - @"cat": category, - @"ph": @"X", - @"ts": start, - @"dur": @(RCTProfileTimestamp(CACurrentMediaTime()).doubleValue - start.doubleValue), - @"args": RCTProfileMergeArgs(event[3], args), - ); + RCTProfileAddEvent(RCTProfileTraceEvents, + @"tid": threadName, + @"name": event[2], + @"cat": category, + @"ph": @"X", + @"ts": start, + @"dur": @(RCTProfileTimestamp(time).doubleValue - start.doubleValue), + @"args": RCTProfileMergeArgs(event[3], args), ); } @@ -409,19 +418,22 @@ int RCTProfileBeginAsyncEvent( static int eventID = 0; + NSTimeInterval time = CACurrentMediaTime(); + int currentEventID = ++eventID; + if (callbacks != NULL) { callbacks->begin_async_section(tag, name.UTF8String, eventID, args.count, RCTProfileSystraceArgsFromNSDictionary(args)); } else { - RCTProfileLock( - RCTProfileOngoingEvents[@(eventID)] = @[ - RCTProfileTimestamp(CACurrentMediaTime()), + dispatch_async(RCTProfileGetQueue(), ^{ + RCTProfileOngoingEvents[@(currentEventID)] = @[ + RCTProfileTimestamp(time), name, RCTNullIfNil(args), ]; - ); + }); } - return eventID++; + return currentEventID; } void RCTProfileEndAsyncEvent( @@ -438,12 +450,17 @@ void RCTProfileEndAsyncEvent( return; } - RCTProfileLock( + NSTimeInterval time = CACurrentMediaTime(); + NSString *threadName = RCTCurrentThreadName(); + + dispatch_async(RCTProfileGetQueue(), ^{ NSArray *event = RCTProfileOngoingEvents[@(cookie)]; + if (event) { - NSNumber *endTimestamp = RCTProfileTimestamp(CACurrentMediaTime()); + NSNumber *endTimestamp = RCTProfileTimestamp(time); RCTProfileAddEvent(RCTProfileTraceEvents, + @"tid": threadName, @"name": event[1], @"cat": category, @"ph": @"X", @@ -453,7 +470,7 @@ void RCTProfileEndAsyncEvent( ); [RCTProfileOngoingEvents removeObjectForKey:@(cookie)]; } - ); + }); } void RCTProfileImmediateEvent( @@ -468,15 +485,19 @@ void RCTProfileImmediateEvent( return; } - RCTProfileLock( + NSTimeInterval time = CACurrentMediaTime(); + NSString *threadName = RCTCurrentThreadName(); + + dispatch_async(RCTProfileGetQueue(), ^{ RCTProfileAddEvent(RCTProfileTraceEvents, + @"tid": threadName, @"name": name, - @"ts": RCTProfileTimestamp(CACurrentMediaTime()), + @"ts": RCTProfileTimestamp(time), @"scope": @(scope), @"ph": @"i", @"args": RCTProfileGetMemoryUsage(), ); - ); + }); } NSNumber *_RCTProfileBeginFlowEvent(void) @@ -490,17 +511,23 @@ NSNumber *_RCTProfileBeginFlowEvent(void) return @0; } - RCTProfileLock( + NSTimeInterval time = CACurrentMediaTime(); + NSNumber *currentID = @(++flowID); + NSString *threadName = RCTCurrentThreadName(); + + dispatch_async(RCTProfileGetQueue(), ^{ RCTProfileAddEvent(RCTProfileTraceEvents, + @"tid": threadName, @"name": @"flow", - @"id": @(++flowID), + @"id": currentID, @"cat": @"flow", @"ph": @"s", - @"ts": RCTProfileTimestamp(CACurrentMediaTime()), + @"ts": RCTProfileTimestamp(time), ); - ); - return @(flowID); + }); + + return currentID; } void _RCTProfileEndFlowEvent(NSNumber *flowID) @@ -511,15 +538,19 @@ void _RCTProfileEndFlowEvent(NSNumber *flowID) return; } - RCTProfileLock( + NSTimeInterval time = CACurrentMediaTime(); + NSString *threadName = RCTCurrentThreadName(); + + dispatch_async(RCTProfileGetQueue(), ^{ RCTProfileAddEvent(RCTProfileTraceEvents, + @"tid": threadName, @"name": @"flow", @"id": flowID, @"cat": @"flow", @"ph": @"f", - @"ts": RCTProfileTimestamp(CACurrentMediaTime()), + @"ts": RCTProfileTimestamp(time), ); - ); + }); } void RCTProfileSendResult(RCTBridge *bridge, NSString *route, NSData *data)