From 4595ebc06e58d7ded08308fc3f4f8d0333c97d6a Mon Sep 17 00:00:00 2001 From: appleguy Date: Thu, 13 Oct 2016 10:31:22 -0700 Subject: [PATCH] [ASLog] Add new ASProfilingSignpost defines for System Trace flags. (#2370) * [Debugging / Profiling] Add kdebug_signpost calls to Range and DataController. * [ASLog] Add new ASProfilingSignpost defines for System Trace flags. * [ASLog] Improve kdebug_signpost logging: ASRunloopQueue and AsyncDisplay, and colors. See https://github.com/facebook/AsyncDisplayKit/pull/2370 for screenshots. --- AsyncDisplayKit/ASRunLoopQueue.mm | 4 +++ AsyncDisplayKit/Details/ASDataController.mm | 6 ++++ AsyncDisplayKit/Details/ASRangeController.mm | 7 +++- .../Transactions/_ASAsyncTransaction.mm | 7 ++-- Base/ASBaseDefines.h | 2 ++ Base/ASLog.h | 36 +++++++++++++++++++ 6 files changed, 59 insertions(+), 3 deletions(-) diff --git a/AsyncDisplayKit/ASRunLoopQueue.mm b/AsyncDisplayKit/ASRunLoopQueue.mm index 44621b667d..e9be82de0d 100644 --- a/AsyncDisplayKit/ASRunLoopQueue.mm +++ b/AsyncDisplayKit/ASRunLoopQueue.mm @@ -110,6 +110,8 @@ static void runLoopSourceCallback(void *info) { if (_internalQueue.empty()) { return; } + + ASProfilingSignpostStart(0, self); // Snatch the next batch of items. NSUInteger totalNodeCount = _internalQueue.size(); @@ -138,6 +140,8 @@ static void runLoopSourceCallback(void *info) { CFRunLoopSourceSignal(_runLoopSource); CFRunLoopWakeUp(_runLoop); } + + ASProfilingSignpostEnd(0, self); } - (void)enqueue:(id)object diff --git a/AsyncDisplayKit/Details/ASDataController.mm b/AsyncDisplayKit/Details/ASDataController.mm index ea9ffdd75c..7d776d14e8 100644 --- a/AsyncDisplayKit/Details/ASDataController.mm +++ b/AsyncDisplayKit/Details/ASDataController.mm @@ -21,6 +21,8 @@ #import "ASDataController+Subclasses.h" #import "ASDispatch.h" +#import + //#define LOG(...) NSLog(__VA_ARGS__) #define LOG(...) @@ -136,6 +138,8 @@ NSString * const ASDataControllerRowNodeKind = @"_ASDataControllerRowNodeKind"; [ASDataController _expectToInsertNodes:contexts.count]; #endif + ASProfilingSignpostStart(2, _dataSource); + NSUInteger blockSize = [[ASDataController class] parallelProcessorCount] * kASDataControllerSizingCountPerProcessor; NSUInteger count = contexts.count; @@ -147,6 +151,8 @@ NSString * const ASDataControllerRowNodeKind = @"_ASDataControllerRowNodeKind"; NSArray *indexPaths = [ASIndexedNodeContext indexPathsFromContexts:batchedContexts]; batchCompletionHandler(nodes, indexPaths); } + + ASProfilingSignpostEnd(2, _dataSource); } /** diff --git a/AsyncDisplayKit/Details/ASRangeController.mm b/AsyncDisplayKit/Details/ASRangeController.mm index fdd87af0f2..ab4dfc7e3e 100644 --- a/AsyncDisplayKit/Details/ASRangeController.mm +++ b/AsyncDisplayKit/Details/ASRangeController.mm @@ -22,6 +22,8 @@ #import "ASDisplayNode+FrameworkPrivate.h" #import "AsyncDisplayKit+Debug.h" +#import + #define AS_RANGECONTROLLER_LOG_UPDATE_FREQ 0 @interface ASRangeController () @@ -188,7 +190,8 @@ static UIApplicationState __ApplicationState = UIApplicationStateActive; if (visibleNodePaths.count == 0) { // if we don't have any visibleNodes currently (scrolled before or after content)... return; // don't do anything for this update, but leave _rangeIsValid == NO to make sure we update it later } - + ASProfilingSignpostStart(1, self); + ASScrollDirection scrollDirection = [_dataSource scrollDirectionForRangeController:self]; if (_layoutControllerImplementsSetViewportSize) { [_layoutController setViewportSize:[_dataSource viewportSizeForRangeController:self]]; @@ -375,6 +378,8 @@ static UIApplicationState __ApplicationState = UIApplicationStateActive; NSLog(@"Range update complete; modifiedIndexPaths: %@", [self descriptionWithIndexPaths:modifiedIndexPaths]); #endif [_delegate didCompleteUpdatesInRangeController:self]; + + ASProfilingSignpostEnd(1, self); } #pragma mark - Notification observers diff --git a/AsyncDisplayKit/Details/Transactions/_ASAsyncTransaction.mm b/AsyncDisplayKit/Details/Transactions/_ASAsyncTransaction.mm index 59df1fd14c..c1fde78b55 100644 --- a/AsyncDisplayKit/Details/Transactions/_ASAsyncTransaction.mm +++ b/AsyncDisplayKit/Details/Transactions/_ASAsyncTransaction.mm @@ -13,7 +13,9 @@ #import "_ASAsyncTransaction.h" #import "_ASAsyncTransactionGroup.h" - +#import "ASAssert.h" +#import "ASLog.h" +#import "ASThread.h" #import #import #import @@ -242,10 +244,11 @@ void ASAsyncTransactionQueue::GroupImpl::schedule(NSInteger priority, dispatch_q // go until there are no more pending operations while (!entry._operationQueue.empty()) { Operation operation = entry.popNextOperation(respectPriority); - lock.unlock(); if (operation._block) { + ASProfilingSignpostStart(3, operation._block); operation._block(); + ASProfilingSignpostEnd(3, operation._block); } operation._group->leave(); operation._block = nil; // the block must be freed while mutex is unlocked diff --git a/Base/ASBaseDefines.h b/Base/ASBaseDefines.h index e7e1e8a21a..265c1544de 100755 --- a/Base/ASBaseDefines.h +++ b/Base/ASBaseDefines.h @@ -10,6 +10,8 @@ #pragma once +#import "ASLog.h" + // The C++ compiler mangles C function names. extern "C" { /* your C functions */ } prevents this. // You should wrap all C function prototypes declared in headers with ASDISPLAYNODE_EXTERN_C_BEGIN/END, even if // they are included only from .m (Objective-C) files. It's common for .m files to start using C++ diff --git a/Base/ASLog.h b/Base/ASLog.h index 4ba3361c68..8f0d1e3cfe 100644 --- a/Base/ASLog.h +++ b/Base/ASLog.h @@ -10,8 +10,44 @@ #pragma once +#import +#import "ASAvailability.h" + #define ASMultiplexImageNodeLogDebug(...) #define ASMultiplexImageNodeCLogDebug(...) #define ASMultiplexImageNodeLogError(...) #define ASMultiplexImageNodeCLogError(...) + +#if PROFILE +// These definitions are required to build the backward-compatible kdebug trace +// on the iOS 10 SDK. The kdebug_trace function crashes if run on iOS 9 and earlier. +// It's valuable to support trace signposts on iOS 9, because A5 devices don't support iOS 10. +#ifndef DBG_MACH_CHUD +#define DBG_MACH_CHUD 0x0A +#define DBG_FUNC_START 1 +#define DBG_FUNC_END 2 +#define DBG_APPS 33 +#define SYS_kdebug_trace 180 +#define KDBG_CODE(Class, SubClass, code) (((Class & 0xff) << 24) | ((SubClass & 0xff) << 16) | ((code & 0x3fff) << 2)) +#define APPSDBG_CODE(SubClass,code) KDBG_CODE(DBG_APPS, SubClass, code) +#endif + +#define ASProfilingSignpost(x) \ + AS_AT_LEAST_IOS10 ? kdebug_signpost(x, 0, 0, 0, (uint32_t)(x % 4)) \ + : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, x) | DBG_FUNC_NONE, 0, 0, 0, (uint32_t)(x % 4)); + +#define ASProfilingSignpostStart(x, y) \ + AS_AT_LEAST_IOS10 ? kdebug_signpost_start((uint32_t)x, (uintptr_t)y, 0, 0, (uint32_t)(x % 4)) \ + : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, x) | DBG_FUNC_START, (uintptr_t)y, 0, 0, (uint32_t)(x % 4)); + +#define ASProfilingSignpostEnd(x, y) \ + AS_AT_LEAST_IOS10 ? kdebug_signpost_end((uint32_t)x, (uintptr_t)y, 0, 0, (uint32_t)(x % 4)) \ + : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, x) | DBG_FUNC_END, (uintptr_t)y, 0, 0, (uint32_t)(x % 4)); +#else + +#define ASProfilingSignpost(x) +#define ASProfilingSignpostStart(x, y) +#define ASProfilingSignpostEnd(x, y) + +#endif