Improve System Trace Implementation #trivial (#368)

* Improve the kdebug, system trace integration

* Remove superseded subsystem

* Address review comments

* Please the license header gods

* Address harder

* Fix node block retaining collection view

AsyncDisplayKit.xcodeproj/project.pbxproj

@@ -2627,6 +2627,7 @@
 				GCC_INSTRUMENT_PROGRAM_FLOW_ARCS = NO;
 				GCC_NO_COMMON_BLOCKS = YES;
 				GCC_PRECOMPILE_PREFIX_HEADER = YES;
+				GCC_PREPROCESSOR_DEFINITIONS = "PROFILE=1";
 				INFOPLIST_FILE = "$(SRCROOT)/Source/Info.plist";
 				INSTALL_PATH = "$(LOCAL_LIBRARY_DIR)/Frameworks";
 				LD_RUNPATH_SEARCH_PATHS = "$(inherited) @executable_path/Frameworks @loader_path/Frameworks";

Source/ASCollectionView.mm

@@ -1675,7 +1675,7 @@ - (ASCellNodeBlock)dataController:(ASDataController *)dataController nodeBlockAt
     if (node.interactionDelegate == nil) {
       node.interactionDelegate = strongSelf;
     }
-    if (_inverted) {
+    if (strongSelf.inverted) {
       node.transform = CATransform3DMakeScale(1, -1, 1) ;
     }
     return node;

Source/ASDisplayNode.mm

@@ -957,9 +957,25 @@ - (ASLayout *)calculateLayoutThatFits:(ASSizeRange)constrainedSize
                      restrictedToSize:(ASLayoutElementSize)size
                  relativeToParentSize:(CGSize)parentSize
 {
+  // Use a pthread specific to mark when this method is called re-entrant on same thread.
+  // We only want one calculateLayout signpost interval per thread.
+  // This is fast enough to do it unconditionally.
+  auto key = ASPthreadStaticKey(NULL);
+  BOOL isRootCall = (pthread_getspecific(key) == NULL);
+  if (isRootCall) {
+    pthread_setspecific(key, kCFBooleanTrue);
+    ASSignpostStart(ASSignpostCalculateLayout);
+  }
+
   ASSizeRange styleAndParentSize = ASLayoutElementSizeResolve(self.style.size, parentSize);
   const ASSizeRange resolvedRange = ASSizeRangeIntersect(constrainedSize, styleAndParentSize);
-  return [self calculateLayoutThatFits:resolvedRange];
+  ASLayout *result = [self calculateLayoutThatFits:resolvedRange];
+
+  if (isRootCall) {
+    pthread_setspecific(key, NULL);
+    ASSignpostEnd(ASSignpostCalculateLayout);
+  }
+  return result;
 }
 
 - (ASLayout *)calculateLayoutThatFits:(ASSizeRange)constrainedSize

Source/ASRunLoopQueue.mm

@@ -19,7 +19,7 @@
 #import <AsyncDisplayKit/ASRunLoopQueue.h>
 #import <AsyncDisplayKit/ASThread.h>
 #import <AsyncDisplayKit/ASLog.h>
-
+#import <QuartzCore/QuartzCore.h>
 #import <cstdlib>
 #import <deque>
 #import <vector>
@@ -78,16 +78,20 @@ - (void)threadMain
         return;
       }
       // The scope below is entered while already locked. @autorelease is crucial here; see PR 2890.
+      NSInteger count;
       @autoreleasepool {
 #if ASRunLoopQueueLoggingEnabled
         NSLog(@"ASDeallocQueue Processing: %lu objects destroyed", weakSelf->_queue.size());
 #endif
         // Sometimes we release 10,000 objects at a time.  Don't hold the lock while releasing.
         std::deque<id> currentQueue = weakSelf->_queue;
+        count = currentQueue.size();
+        ASSignpostStartCustom(ASSignpostDeallocQueueDrain, self, count);
         weakSelf->_queue = std::deque<id>();
         weakSelf->_queueLock.unlock();
         currentQueue.clear();
       }
+      ASSignpostEndCustom(ASSignpostDeallocQueueDrain, self, count, ASSignpostColorDefault);
     });
 
     CFRunLoopRef runloop = CFRunLoopGetCurrent();
@@ -196,8 +200,69 @@ @interface ASRunLoopQueue () {
 
 @end
 
+#if AS_KDEBUG_ENABLE
+/**
+ * This is real, private CA API. Valid as of iOS 10.
+ */
+typedef enum {
+  kCATransactionPhasePreLayout,
+  kCATransactionPhasePreCommit,
+  kCATransactionPhasePostCommit,
+} CATransactionPhase;
+
+@interface CATransaction (Private)
++ (void)addCommitHandler:(void(^)(void))block forPhase:(CATransactionPhase)phase;
++ (int)currentState;
+@end
+#endif
+
 @implementation ASRunLoopQueue
 
+#if AS_KDEBUG_ENABLE
++ (void)load
+{
+  [self registerCATransactionObservers];
+}
+
++ (void)registerCATransactionObservers
+{
+  static BOOL privateCAMethodsExist;
+  static dispatch_block_t preLayoutHandler;
+  static dispatch_block_t preCommitHandler;
+  static dispatch_block_t postCommitHandler;
+  static dispatch_once_t onceToken;
+  dispatch_once(&onceToken, ^{
+    privateCAMethodsExist = [CATransaction respondsToSelector:@selector(addCommitHandler:forPhase:)];
+    privateCAMethodsExist &= [CATransaction respondsToSelector:@selector(currentState)];
+    if (!privateCAMethodsExist) {
+      NSLog(@"Private CA methods are gone.");
+    }
+    preLayoutHandler = ^{
+      ASSignpostStartCustom(ASSignpostCATransactionLayout, 0, [CATransaction currentState]);
+    };
+    preCommitHandler = ^{
+      int state = [CATransaction currentState];
+      ASSignpostEndCustom(ASSignpostCATransactionLayout, 0, state, ASSignpostColorDefault);
+      ASSignpostStartCustom(ASSignpostCATransactionCommit, 0, state);
+    };
+    postCommitHandler = ^{
+      ASSignpostEndCustom(ASSignpostCATransactionCommit, 0, [CATransaction currentState], ASSignpostColorDefault);
+      // Can't add new observers inside an observer. rdar://problem/31253952
+      dispatch_async(dispatch_get_main_queue(), ^{
+        [self registerCATransactionObservers];
+      });
+    };
+  });
+
+  if (privateCAMethodsExist) {
+    [CATransaction addCommitHandler:preLayoutHandler forPhase:kCATransactionPhasePreLayout];
+    [CATransaction addCommitHandler:preCommitHandler forPhase:kCATransactionPhasePreCommit];
+    [CATransaction addCommitHandler:postCommitHandler forPhase:kCATransactionPhasePostCommit];
+  }
+}
+
+#endif // AS_KDEBUG_ENABLE
+
 - (instancetype)initWithRunLoop:(CFRunLoopRef)runloop retainObjects:(BOOL)retainsObjects handler:(void (^)(id _Nullable, BOOL))handlerBlock
 {
   if (self = [super init]) {
@@ -275,7 +340,7 @@ - (void)processQueue
       return;
     }
 
-    ASProfilingSignpostStart(0, self);
+    ASSignpostStart(ASSignpostRunLoopQueueBatch);
 
     // Snatch the next batch of items.
     NSInteger maxCountToProcess = MIN(internalQueueCount, self.batchSize);
@@ -329,7 +394,7 @@ - (void)processQueue
     CFRunLoopWakeUp(_runLoop);
   }
 
-  ASProfilingSignpostEnd(0, self);
+  ASSignpostEnd(ASSignpostRunLoopQueueBatch);
 }
 
 - (void)enqueue:(id)object

Source/Base/ASAssert.m

@@ -13,15 +13,9 @@
 #import <AsyncDisplayKit/ASAssert.h>
 #import <Foundation/Foundation.h>
 
-// pthread_key_create must be called before the key can be used. This function does that.
 static pthread_key_t ASMainThreadAssertionsDisabledKey()
 {
-  static pthread_key_t ASMainThreadAssertionsDisabledKey;
-  static dispatch_once_t onceToken;
-  dispatch_once(&onceToken, ^{
-    pthread_key_create(&ASMainThreadAssertionsDisabledKey, NULL);
-  });
-  return ASMainThreadAssertionsDisabledKey;
+  return ASPthreadStaticKey(NULL);
 }
 
 BOOL ASMainThreadAssertionsAreDisabled() {

Source/Base/ASBaseDefines.h

@@ -215,6 +215,24 @@
 #define AS_SUBCLASSING_RESTRICTED
 #endif
 
+#define ASPthreadStaticKey(dtor) ({ \
+  static dispatch_once_t onceToken; \
+  static pthread_key_t key; \
+  dispatch_once(&onceToken, ^{ \
+    pthread_key_create(&key, dtor); \
+  }); \
+  key; \
+})
+
+#define ASCreateOnce(expr) ({ \
+  static dispatch_once_t onceToken; \
+  static __typeof__(expr) staticVar; \
+  dispatch_once(&onceToken, ^{ \
+    staticVar = expr; \
+  }); \
+  staticVar; \
+})
+
 /// Ensure that class is of certain kind
 #define ASDynamicCast(x, c) ({ \
   id __val = x;\

Source/Base/ASLog.h

@@ -16,18 +16,55 @@
 //
 
 #import <AsyncDisplayKit/ASAvailability.h>
+#import <Foundation/Foundation.h>
 
-#pragma once
+/// The signposts we use. Signposts are grouped by color. The SystemTrace.tracetemplate file
+/// should be kept up-to-date with these values.
+typedef NS_ENUM(uint32_t, ASSignpostName) {
+  // Collection/Table (Blue)
+  ASSignpostDataControllerBatch = 300,		// Alloc/layout nodes before collection update.
+  ASSignpostRangeControllerUpdate,				// Ranges update pass.
+  ASSignpostCollectionUpdate,							// Entire update process, from -endUpdates to [super perform…]
 
+  // Rendering (Green)
+  ASSignpostLayerDisplay = 325,						// Client display callout.
+  ASSignpostRunLoopQueueBatch,						// One batch of ASRunLoopQueue.
+
+  // Layout (Purple)
+  ASSignpostCalculateLayout = 350,				// Start of calculateLayoutThatFits to end. Max 1 per thread.
+
+  // Misc (Orange)
+  ASSignpostDeallocQueueDrain = 375,			// One chunk of dealloc queue work. arg0 is count.
+  ASSignpostCATransactionLayout,					// The CA transaction commit layout phase.
+  ASSignpostCATransactionCommit						// The CA transaction commit post-layout phase.
+};
+
+typedef NS_ENUM(uintptr_t, ASSignpostColor) {
+  ASSignpostColorBlue,
+  ASSignpostColorGreen,
+  ASSignpostColorPurple,
+  ASSignpostColorOrange,
+  ASSignpostColorRed,
+  ASSignpostColorDefault
+};
+
+static inline ASSignpostColor ASSignpostGetColor(ASSignpostName name, ASSignpostColor colorPref) {
+  if (colorPref == ASSignpostColorDefault) {
+    return (ASSignpostColor)((name / 25) % 4);
+  } else {
+    return colorPref;
+  }
+}
 
 #define ASMultiplexImageNodeLogDebug(...)
 #define ASMultiplexImageNodeCLogDebug(...)
 
 #define ASMultiplexImageNodeLogError(...)
 #define ASMultiplexImageNodeCLogError(...)
 
-// Note: `<sys/kdebug_signpost.h>` only exists in Xcode 8 and later.
-#if defined(PROFILE) && __has_include(<sys/kdebug_signpost.h>)
+#define AS_KDEBUG_ENABLE defined(PROFILE) && __has_include(<sys/kdebug_signpost.h>)
+
+#if AS_KDEBUG_ENABLE
 
 #import <sys/kdebug_signpost.h>
 
@@ -45,21 +82,27 @@
 #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));
+// Currently we'll reserve arg3.
+#define ASSignpost(name, identifier, arg2, color) \
+  AS_AT_LEAST_IOS10 ? kdebug_signpost(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color)) \
+                    : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_NONE, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color));
+
+#define ASSignpostStartCustom(name, identifier, arg2) \
+  AS_AT_LEAST_IOS10 ? kdebug_signpost_start(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, 0) \
+                    : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_START, (uintptr_t)identifier, (uintptr_t)arg2, 0, 0);
+#define ASSignpostStart(name) ASSignpostStartCustom(name, self, 0)
 
-#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 ASSignpostEndCustom(name, identifier, arg2, color) \
+  AS_AT_LEAST_IOS10 ? kdebug_signpost_end(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color)) \
+                    : syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_END, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color));
+#define ASSignpostEnd(name) ASSignpostEndCustom(name, self, 0, ASSignpostColorDefault)
 
-#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)
+#define ASSignpost(name, identifier, arg2, color)
+#define ASSignpostStartCustom(name, identifier, arg2)
+#define ASSignpostStart(name)
+#define ASSignpostEndCustom(name, identifier, arg2, color)
+#define ASSignpostEnd(name)
 
 #endif

Source/Details/ASDataController.mm

@@ -40,8 +40,6 @@
 //#define LOG(...) NSLog(__VA_ARGS__)
 #define LOG(...)
 
-#define AS_MEASURE_AVOIDED_DATACONTROLLER_WORK 0
-
 #define RETURN_IF_NO_DATASOURCE(val) if (_dataSource == nil) { return val; }
 #define ASSERT_ON_EDITING_QUEUE ASDisplayNodeAssertNotNil(dispatch_get_specific(&kASDataControllerEditingQueueKey), @"%@ must be called on the editing transaction queue.", NSStringFromSelector(_cmd))
 
@@ -54,13 +52,6 @@
 
 typedef void (^ASDataControllerCompletionBlock)(NSArray<ASCollectionElement *> *elements, NSArray<ASCellNode *> *nodes);
 
-#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
-@interface ASDataController (AvoidedWorkMeasuring)
-+ (void)_didLayoutNode;
-+ (void)_expectToInsertNodes:(NSUInteger)count;
-@end
-#endif
-
 @interface ASDataController () {
   id<ASDataControllerLayoutDelegate> _layoutDelegate;
 
@@ -159,17 +150,14 @@ - (void)setLayoutDelegate:(id<ASDataControllerLayoutDelegate>)layoutDelegate
 - (void)batchAllocateNodesFromElements:(NSArray<ASCollectionElement *> *)elements andLayout:(BOOL)shouldLayout batchSize:(NSInteger)batchSize batchCompletion:(ASDataControllerCompletionBlock)batchCompletionHandler
 {
   ASSERT_ON_EDITING_QUEUE;
-#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
-    [ASDataController _expectToInsertNodes:elements.count];
-#endif
-
+
   if (elements.count == 0 || _dataSource == nil) {
     batchCompletionHandler(@[], @[]);
     return;
   }
 
-  ASProfilingSignpostStart(2, _dataSource);
-  
+  ASSignpostStart(ASSignpostDataControllerBatch);
+
   if (batchSize == 0) {
     batchSize = [[ASDataController class] parallelProcessorCount] * kASDataControllerSizingCountPerProcessor;
   }
@@ -182,8 +170,8 @@ - (void)batchAllocateNodesFromElements:(NSArray<ASCollectionElement *> *)element
     NSArray<ASCellNode *> *nodes = [self _allocateNodesFromElements:batchedElements andLayout:shouldLayout];
     batchCompletionHandler(batchedElements, nodes);
   }
-  
-  ASProfilingSignpostEnd(2, _dataSource);
+
+  ASSignpostEndCustom(ASSignpostDataControllerBatch, self, 0, (_dataSource != nil ? ASSignpostColorDefault : ASSignpostColorRed));
 }
 
 /**
@@ -228,10 +216,6 @@ - (void)_layoutNode:(ASCellNode *)node withConstrainedSize:(ASSizeRange)constrai
       if (ASSizeRangeHasSignificantArea(sizeRange)) {
         [self _layoutNode:node withConstrainedSize:sizeRange];
       }
-
-#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
-      [ASDataController _didLayoutNode];
-#endif
     }
 
     allocatedNodeBuffer[i] = node;
@@ -836,27 +820,3 @@ - (void)_scheduleBlockOnMainSerialQueue:(dispatch_block_t)block
 }
 
 @end
-
-#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
-
-static volatile int64_t _totalExpectedItems = 0;
-static volatile int64_t _totalMeasuredNodes = 0;
-
-@implementation ASDataController (WorkMeasuring)
-
-+ (void)_didLayoutNode
-{
-    int64_t measured = OSAtomicIncrement64(&_totalMeasuredNodes);
-    int64_t expected = _totalExpectedItems;
-    if (measured % 20 == 0 || measured == expected) {
-        NSLog(@"Data controller avoided work (underestimated): %lld / %lld", measured, expected);
-    }
-}
-
-+ (void)_expectToInsertNodes:(NSUInteger)count
-{
-    OSAtomicAdd64((int64_t)count, &_totalExpectedItems);
-}
-
-@end
-#endif