ASSignpost: Add support for the os_signpost API, fixes (#1501)

* ASSignpost: Add support for the os_signpost API

- Removes support for colored intervals. These weren't really useful and they aren't part of the signpost api.
- Fixes an issue with range controller interval logging.
- Adds an interval for interface orientation changes.

* Rename

* Support Xcode 9

* Commentary

Source/ASDisplayNode.mm

@@ -1110,12 +1110,12 @@ ASSynthesizeLockingMethodsWithMutex(__instanceLock__);
   as_activity_scope_verbose(as_activity_create("Calculate node layout", AS_ACTIVITY_CURRENT, OS_ACTIVITY_FLAG_DEFAULT));
   as_log_verbose(ASLayoutLog(), "Calculating layout for %@ sizeRange %@", self, NSStringFromASSizeRange(constrainedSize));
 
-#if AS_KDEBUG_ENABLE
+#if AS_SIGNPOST_ENABLE
   // We only want one calculateLayout signpost interval per thread.
   // Currently there is no fallback for profiling i386, since it's not useful.
   static _Thread_local NSInteger tls_callDepth;
   if (tls_callDepth++ == 0) {
-    ASSignpostStart(ASSignpostCalculateLayout);
+    ASSignpostStart(CalculateLayout, self, "%@", ASObjectDescriptionMakeTiny(self));
   }
 #endif
 
@@ -1124,9 +1124,9 @@ ASSynthesizeLockingMethodsWithMutex(__instanceLock__);
   ASLayout *result = [self calculateLayoutThatFits:resolvedRange];
   as_log_verbose(ASLayoutLog(), "Calculated layout %@", result);
 
-#if AS_KDEBUG_ENABLE
+#if AS_SIGNPOST_ENABLE
   if (--tls_callDepth == 0) {
-    ASSignpostEnd(ASSignpostCalculateLayout);
+    ASSignpostEnd(CalculateLayout, self, "");
   }
 #endif
   

Source/ASRunLoopQueue.mm

@@ -215,7 +215,7 @@ static void runLoopSourceCallback(void *info) {
       return;
     }
 
-    ASSignpostStart(ASSignpostRunLoopQueueBatch);
+    ASSignpostStart(RunLoopQueueBatch, self, "%s", object_getClassName(self));
 
     // Snatch the next batch of items.
     NSInteger maxCountToProcess = MIN(internalQueueCount, self.batchSize);
@@ -278,7 +278,7 @@ static void runLoopSourceCallback(void *info) {
     CFRunLoopWakeUp(_runLoop);
   }
   
-  ASSignpostEnd(ASSignpostRunLoopQueueBatch);
+  ASSignpostEnd(RunLoopQueueBatch, self, "count: %d", (int)count);
 }
 
 - (void)enqueue:(id)object
@@ -440,7 +440,7 @@ dispatch_once_t _ASSharedCATransactionQueueOnceToken;
     return;
   }
   as_activity_scope_verbose(as_activity_create("Process run loop queue batch", _rootActivity, OS_ACTIVITY_FLAG_DEFAULT));
-  ASSignpostStart(ASSignpostRunLoopQueueBatch);
+  ASSignpostStart(RunLoopQueueBatch, self, "CATransactionQueue");
   
   // Swap buffers, clear our hash table.
   _internalQueue.swap(_batchBuffer);
@@ -455,7 +455,7 @@ dispatch_once_t _ASSharedCATransactionQueueOnceToken;
   }
   _batchBuffer.clear();
   as_log_verbose(ASDisplayLog(), "processed %lu items", (unsigned long)count);
-  ASSignpostEnd(ASSignpostRunLoopQueueBatch);
+  ASSignpostEnd(RunLoopQueueBatch, self, "count: %d", (int)count);
 }
 
 - (void)enqueue:(id<ASCATransactionQueueObserving>)object

Source/Base/ASBaseDefines.h

@@ -123,6 +123,8 @@
 
 #define ASOVERLOADABLE __attribute__((overloadable))
 
+/// Xcode >= 10.
+#define AS_HAS_OS_SIGNPOST __has_include(<os/signpost.h>)
 
 #if __has_attribute(noescape)
 #define AS_NOESCAPE __attribute__((noescape))

Source/Base/ASLog.h

@@ -69,6 +69,11 @@ AS_EXTERN os_log_t ASMainThreadDeallocationLog(void);
 #define ASLockingLogEnabled 0
 AS_EXTERN os_log_t ASLockingLog(void);
 
+#if AS_HAS_OS_SIGNPOST
+/// Uses the special POI category for Instruments. Used by ASSignpost.h.
+AS_EXTERN os_log_t ASPointsOfInterestLog(void);
+#endif
+
 /**
  * The activity tracing system changed a lot between iOS 9 and 10.
  * In iOS 10, the system was merged with logging and became much more powerful

Source/Base/ASLog.mm

@@ -8,6 +8,9 @@
 
 #import <AsyncDisplayKit/ASLog.h>
 #import <stdatomic.h>
+#if AS_HAS_OS_SIGNPOST
+#import <os/signpost.h>
+#endif
 
 static atomic_bool __ASLogEnabled = ATOMIC_VAR_INIT(YES);
 
@@ -50,3 +53,9 @@ os_log_t ASMainThreadDeallocationLog() {
 os_log_t ASLockingLog() {
   return (ASLockingLogEnabled && ASLoggingIsEnabled()) ? ASCreateOnce(os_log_create("org.TextureGroup.Texture", "Locking")) : OS_LOG_DISABLED;
 }
+
+#if AS_HAS_OS_SIGNPOST
+os_log_t ASPointsOfInterestLog() {
+  return ASCreateOnce(os_log_create("org.TextureGroup.Texture", OS_LOG_CATEGORY_POINTS_OF_INTEREST));
+}
+#endif

Source/Base/ASSignpost.h

@@ -9,50 +9,34 @@
 /// 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)
+  // Collection/Table
   ASSignpostDataControllerBatch = 300,    // Alloc/layout nodes before collection update.
   ASSignpostRangeControllerUpdate,        // Ranges update pass.
-  ASSignpostCollectionUpdate,             // Entire update process, from -endUpdates to [super perform…]
   
-  // Rendering (Green)
+  // Rendering
   ASSignpostLayerDisplay = 325,           // Client display callout.
   ASSignpostRunLoopQueueBatch,            // One batch of ASRunLoopQueue.
   
-  // Layout (Purple)
+  // Layout
   ASSignpostCalculateLayout = 350,        // Start of calculateLayoutThatFits to end. Max 1 per thread.
   
-  // Misc (Orange)
+  // Misc
   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.
+  ASSignpostOrientationChange,            // From WillChangeStatusBarOrientation to animation end.
 };
 
-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;
-  }
-}
-
-#if defined(PROFILE) && __has_include(<sys/kdebug_signpost.h>)
-  #define AS_KDEBUG_ENABLE 1
+#ifdef PROFILE
+  #define AS_SIGNPOST_ENABLE 1
 #else
-  #define AS_KDEBUG_ENABLE 0
+  #define AS_SIGNPOST_ENABLE 0
 #endif
 
-#if AS_KDEBUG_ENABLE
+#if AS_SIGNPOST_ENABLE
 
 #import <sys/kdebug_signpost.h>
+#if AS_HAS_OS_SIGNPOST
+#import <os/signpost.h>
+#endif
 
 // 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.
@@ -68,27 +52,55 @@ static inline ASSignpostColor ASSignpostGetColor(ASSignpostName name, ASSignpost
 #define APPSDBG_CODE(SubClass,code) KDBG_CODE(DBG_APPS, SubClass, code)
 #endif
 
-// 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));
+#if AS_HAS_OS_SIGNPOST
 
-#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 ASSignpostStart(name, identifier, format, ...) ({\
+  if (AS_AVAILABLE_IOS_TVOS(12, 12)) { \
+    unowned os_log_t log = ASPointsOfInterestLog(); \
+    os_signpost_id_t spid = os_signpost_id_make_with_id(log, identifier); \
+    os_signpost_interval_begin(log, spid, #name, format, ##__VA_ARGS__); \
+  } else if (AS_AVAILABLE_IOS_TVOS(10, 10)) { \
+    kdebug_signpost_start(ASSignpost##name, (uintptr_t)identifier, 0, 0, 0); \
+  } else { \
+    syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, ASSignpost##name) | DBG_FUNC_START, (uintptr_t)identifier, 0, 0, 0); \
+  } \
+})
 
-#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 ASSignpostEnd(name, identifier, format, ...) ({\
+  if (AS_AVAILABLE_IOS_TVOS(12, 12)) { \
+    unowned os_log_t log = ASPointsOfInterestLog(); \
+    os_signpost_id_t spid = os_signpost_id_make_with_id(log, identifier); \
+    os_signpost_interval_end(log, spid, #name, format, ##__VA_ARGS__); \
+  } else if (AS_AVAILABLE_IOS_TVOS(10, 10)) { \
+    kdebug_signpost_end(ASSignpost##name, (uintptr_t)identifier, 0, 0, 0); \
+  } else { \
+    syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, ASSignpost##name) | DBG_FUNC_END, (uintptr_t)identifier, 0, 0, 0); \
+  } \
+})
 
-#else
+#else // !AS_HAS_OS_SIGNPOST
 
-#define ASSignpost(name, identifier, arg2, color)
-#define ASSignpostStartCustom(name, identifier, arg2)
-#define ASSignpostStart(name)
-#define ASSignpostEndCustom(name, identifier, arg2, color)
-#define ASSignpostEnd(name)
+#define ASSignpostStart(name, identifier, format, ...) ({\
+  if (AS_AVAILABLE_IOS_TVOS(10, 10)) { \
+    kdebug_signpost_start(ASSignpost##name, (uintptr_t)identifier, 0, 0, 0); \
+  } else { \
+    syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, ASSignpost##name) | DBG_FUNC_START, (uintptr_t)identifier, 0, 0, 0); \
+  } \
+})
+
+#define ASSignpostEnd(name, identifier, format, ...) ({\
+  if (AS_AVAILABLE_IOS_TVOS(10, 10)) { \
+    kdebug_signpost_end(ASSignpost##name, (uintptr_t)identifier, 0, 0, 0); \
+  } else { \
+    syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, ASSignpost##name) | DBG_FUNC_END, (uintptr_t)identifier, 0, 0, 0); \
+  } \
+})
+
+#endif
+
+#else // !AS_SIGNPOST_ENABLE
+
+#define ASSignpostStart(name, identifier, format, ...)
+#define ASSignpostEnd(name, identifier, format, ...)
 
 #endif

Source/Details/ASDataController.mm

@@ -147,7 +147,7 @@ typedef void (^ASDataControllerSynchronizationBlock)();
     return;
   }
 
-  ASSignpostStart(ASSignpostDataControllerBatch);
+  ASSignpostStart(DataControllerBatch, self, "%@", ASObjectDescriptionMakeTiny(weakDataSource));
 
   {
     as_activity_create_for_scope("Data controller batch");
@@ -179,7 +179,7 @@ typedef void (^ASDataControllerSynchronizationBlock)();
     });
   }
 
-  ASSignpostEndCustom(ASSignpostDataControllerBatch, self, 0, (weakDataSource != nil ? ASSignpostColorDefault : ASSignpostColorRed));
+  ASSignpostEnd(DataControllerBatch, self, "count: %lu", (unsigned long)nodeCount);
 }
 
 /**

Source/Details/ASObjectDescriptionHelpers.mm

@@ -85,7 +85,10 @@ NSString *ASObjectDescriptionMake(__autoreleasing id object, NSArray<NSDictionar
 }
 
 NSString *ASObjectDescriptionMakeTiny(__autoreleasing id object) {
-  return ASObjectDescriptionMake(object, nil);
+  static constexpr int kBufSize = 64;
+  char buf[kBufSize];
+  int len = snprintf(buf, kBufSize, "<%s: %p>", object_getClassName(object), object);
+  return (__bridge_transfer NSString *)CFStringCreateWithBytes(NULL, (const UInt8 *)buf, len, kCFStringEncodingASCII, false);
 }
 
 NSString *ASStringWithQuotesIfMultiword(NSString *string) {

Source/Details/ASRangeController.mm

@@ -225,7 +225,7 @@ static UIApplicationState __ApplicationState = UIApplicationStateActive;
   auto visibleElements = [_dataSource visibleElementsForRangeController:self];
   NSHashTable *newVisibleNodes = [NSHashTable hashTableWithOptions:NSHashTableObjectPointerPersonality];
 
-  ASSignpostStart(ASSignpostRangeControllerUpdate);
+  ASSignpostStart(RangeControllerUpdate, _dataSource, "%@", ASObjectDescriptionMakeTiny(_dataSource));
 
   // Get the scroll direction. Default to using the previous one, if they're not scrolling.
   ASScrollDirection scrollDirection = [_dataSource scrollDirectionForRangeController:self];
@@ -243,6 +243,7 @@ static UIApplicationState __ApplicationState = UIApplicationStateActive;
       [newVisibleNodes addObject:element.node];
     }
     [self _setVisibleNodes:newVisibleNodes];
+    ASSignpostEnd(RangeControllerUpdate, _dataSource, "");
     return; // don't do anything for this update, but leave _rangeIsValid == NO to make sure we update it later
   }
 
@@ -424,7 +425,7 @@ static UIApplicationState __ApplicationState = UIApplicationStateActive;
   NSLog(@"Range update complete; modifiedIndexPaths: %@, rangeMode: %d", [self descriptionWithIndexPaths:modifiedIndexPaths], rangeMode);
 #endif
   
-  ASSignpostEnd(ASSignpostRangeControllerUpdate);
+  ASSignpostEnd(RangeControllerUpdate, _dataSource, "");
 }
 
 #pragma mark - Notification observers

Source/Private/ASDisplayNode+AsyncDisplay.mm

@@ -262,12 +262,12 @@ using AS::MutexLocker;
    If we're profiling, wrap the display block with signpost start and end.
    Color the interval red if cancelled, green otherwise.
    */
-#if AS_KDEBUG_ENABLE
-  __unsafe_unretained id ptrSelf = self;
+#if AS_SIGNPOST_ENABLE
+  __unsafe_unretained id ptrSelf = (id)self;
   displayBlock = ^{
-    ASSignpostStartCustom(ASSignpostLayerDisplay, ptrSelf, 0);
+    ASSignpostStart(LayerDisplay, ptrSelf, "%@", ASObjectDescriptionMakeTiny(ptrSelf));
     id result = displayBlock();
-    ASSignpostEndCustom(ASSignpostLayerDisplay, ptrSelf, 0, isCancelledBlock() ? ASSignpostColorRed : ASSignpostColorGreen);
+    ASSignpostEnd(LayerDisplay, ptrSelf, "(%d %d), canceled: %d", (int)bounds.size.width, (int)bounds.size.height, (int)isCancelledBlock());
     return result;
   };
 #endif

Source/Private/ASInternalHelpers.mm

@@ -16,6 +16,7 @@
 
 #import <AsyncDisplayKit/ASConfigurationInternal.h>
 #import <AsyncDisplayKit/ASRunLoopQueue.h>
+#import <AsyncDisplayKit/ASSignpost.h>
 #import <AsyncDisplayKit/ASThread.h>
 
 static NSNumber *allowsGroupOpacityFromUIKitOrNil;
@@ -43,6 +44,28 @@ BOOL ASDefaultAllowsEdgeAntialiasing()
   return edgeAntialiasing;
 }
 
+#if AS_SIGNPOST_ENABLE
+void _ASInitializeSignpostObservers(void)
+{
+  // Orientation changes. Unavailable on tvOS.
+#if !TARGET_OS_TV
+  [NSNotificationCenter.defaultCenter addObserverForName:UIApplicationWillChangeStatusBarOrientationNotification object:nil queue:nil usingBlock:^(NSNotification *note) {
+    UIInterfaceOrientation orientation = (UIInterfaceOrientation)[note.userInfo[UIApplicationStatusBarOrientationUserInfoKey] integerValue];
+    ASSignpostStart(OrientationChange, (id)nil, "from %s", UIInterfaceOrientationIsPortrait(orientation) ? "portrait" : "landscape");
+    [CATransaction begin];
+  }];
+  [NSNotificationCenter.defaultCenter addObserverForName:UIApplicationDidChangeStatusBarOrientationNotification object:nil queue:nil usingBlock:^(NSNotification *note) {
+    // When profiling, go ahead and commit the transaction early so that it happens as part of our interval.
+    UIInterfaceOrientation orientation = (UIInterfaceOrientation)[note.userInfo[UIApplicationStatusBarOrientationUserInfoKey] integerValue];
+    [CATransaction setCompletionBlock:^{
+      ASSignpostEnd(OrientationChange, (id)nil, "to %s", UIInterfaceOrientationIsPortrait(orientation) ? "portrait" : "landscape");
+    }];
+    [CATransaction commit];
+  }];
+#endif  // TARGET_OS_TV
+}
+#endif  // AS_SIGNPOST_ENABLE
+
 void ASInitializeFrameworkMainThread(void)
 {
   static dispatch_once_t onceToken;
@@ -57,6 +80,9 @@ void ASInitializeFrameworkMainThread(void)
       allowsEdgeAntialiasingFromUIKitOrNil = @(layer.allowsEdgeAntialiasing);
     }
     ASNotifyInitialized();
+#if AS_SIGNPOST_ENABLE
+    _ASInitializeSignpostObservers();
+#endif
   });
 }