[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

@@ -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

AsyncDisplayKit/Details/ASDataController.mm

@@ -21,6 +21,8 @@
 #import "ASDataController+Subclasses.h"
 #import "ASDispatch.h"
 
+#import <sys/kdebug_signpost.h>
+
 //#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);
 }
 
 /**

AsyncDisplayKit/Details/ASRangeController.mm

@@ -22,6 +22,8 @@
 #import "ASDisplayNode+FrameworkPrivate.h"
 #import "AsyncDisplayKit+Debug.h"
 
+#import <sys/kdebug_signpost.h>
+
 #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

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 <list>
 #import <map>
 #import <mutex>
@@ -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

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++

Base/ASLog.h

@@ -10,8 +10,44 @@
 
 #pragma once
 
+#import <sys/kdebug_signpost.h>
+#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