Overhaul our logging, add activity tracing support. (TextureGroup#399)

* Improve the os_log and os_activity integration

* Address feedback from Scott and Huy

AsyncDisplayKit.xcodeproj/project.pbxproj

@@ -376,6 +376,8 @@
 		CCA282D01E9EBF6C0037E8B7 /* ASTipsWindow.h in Headers */ = {isa = PBXBuildFile; fileRef = CCA282CE1E9EBF6C0037E8B7 /* ASTipsWindow.h */; };
 		CCA282D11E9EBF6C0037E8B7 /* ASTipsWindow.m in Sources */ = {isa = PBXBuildFile; fileRef = CCA282CF1E9EBF6C0037E8B7 /* ASTipsWindow.m */; };
 		CCA5F62E1EECC2A80060C137 /* ASAssert.m in Sources */ = {isa = PBXBuildFile; fileRef = CCA5F62D1EECC2A80060C137 /* ASAssert.m */; };
+		CCB1F95A1EFB60A5009C7475 /* ASLog.m in Sources */ = {isa = PBXBuildFile; fileRef = CCB1F9591EFB60A5009C7475 /* ASLog.m */; };
+		CCB1F95C1EFB6350009C7475 /* ASSignpost.h in Headers */ = {isa = PBXBuildFile; fileRef = CCB1F95B1EFB6316009C7475 /* ASSignpost.h */; };
 		CCB2F34D1D63CCC6004E6DE9 /* ASDisplayNodeSnapshotTests.m in Sources */ = {isa = PBXBuildFile; fileRef = CCB2F34C1D63CCC6004E6DE9 /* ASDisplayNodeSnapshotTests.m */; };
 		CCBBBF5D1EB161760069AA91 /* ASRangeManagingNode.h in Headers */ = {isa = PBXBuildFile; fileRef = CCBBBF5C1EB161760069AA91 /* ASRangeManagingNode.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		CCCCCCD51EC3EF060087FE10 /* ASTextDebugOption.h in Headers */ = {isa = PBXBuildFile; fileRef = CCCCCCC31EC3EF060087FE10 /* ASTextDebugOption.h */; };
@@ -842,6 +844,8 @@
 		CCA282CE1E9EBF6C0037E8B7 /* ASTipsWindow.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = ASTipsWindow.h; sourceTree = "<group>"; };
 		CCA282CF1E9EBF6C0037E8B7 /* ASTipsWindow.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ASTipsWindow.m; sourceTree = "<group>"; };
 		CCA5F62D1EECC2A80060C137 /* ASAssert.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ASAssert.m; sourceTree = "<group>"; };
+		CCB1F9591EFB60A5009C7475 /* ASLog.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ASLog.m; sourceTree = "<group>"; };
+		CCB1F95B1EFB6316009C7475 /* ASSignpost.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = ASSignpost.h; sourceTree = "<group>"; };
 		CCB2F34C1D63CCC6004E6DE9 /* ASDisplayNodeSnapshotTests.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ASDisplayNodeSnapshotTests.m; sourceTree = "<group>"; };
 		CCBBBF5C1EB161760069AA91 /* ASRangeManagingNode.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = ASRangeManagingNode.h; sourceTree = "<group>"; };
 		CCBD05DE1E4147B000D18509 /* ASIGListAdapterBasedDataSource.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ASIGListAdapterBasedDataSource.m; sourceTree = "<group>"; };
@@ -1387,6 +1391,8 @@
 				058D0A44195D058D00B7D73C /* ASBaseDefines.h */,
 				1950C4481A3BB5C1005C8279 /* ASEqualityHelpers.h */,
 				0516FA3B1A15563400B4EBED /* ASLog.h */,
+				CCB1F9591EFB60A5009C7475 /* ASLog.m */,
+				CCB1F95B1EFB6316009C7475 /* ASSignpost.h */,
 			);
 			path = Base;
 			sourceTree = "<group>";
@@ -1692,6 +1698,7 @@
 				9019FBBF1ED8061D00C45F72 /* ASYogaUtilities.h in Headers */,
 				DE84918D1C8FFF2B003D89E9 /* ASRunLoopQueue.h in Headers */,
 				CC0F88621E4281E200576FED /* ASSectionController.h in Headers */,
+				CCB1F95C1EFB6350009C7475 /* ASSignpost.h in Headers */,
 				A2763D7A1CBDD57D00A9ADBD /* ASPINRemoteImageDownloader.h in Headers */,
 				34EFC7611B701C9C00AD841F /* ASBackgroundLayoutSpec.h in Headers */,
 				B35062591B010F070018CF92 /* ASBaseDefines.h in Headers */,
@@ -2180,6 +2187,7 @@
 				B35061F91B010EFD0018CF92 /* ASControlNode.mm in Sources */,
 				8021EC1F1D2B00B100799119 /* UIImage+ASConvenience.m in Sources */,
 				B35062181B010EFD0018CF92 /* ASDataController.mm in Sources */,
+				CCB1F95A1EFB60A5009C7475 /* ASLog.m in Sources */,
 				767E7F8E1C90191D0066C000 /* AsyncDisplayKit+Debug.m in Sources */,
 				CCCCCCD61EC3EF060087FE10 /* ASTextDebugOption.m in Sources */,
 				34EFC75C1B701BD200AD841F /* ASDimension.mm in Sources */,

CHANGELOG.md

@@ -4,6 +4,10 @@
 - [ASTextNode2] Add initial implementation for link handling. [Scott Goodson](https://github.com/appleguy) [#396](https://github.com/TextureGroup/Texture/pull/396)
 - [ASTextNode2] Provide compile flag to globally enable new implementation of ASTextNode: ASTEXTNODE_EXPERIMENT_GLOBAL_ENABLE. [Scott Goodson](https://github.com/appleguy) [#396](https://github.com/TextureGroup/Texture/pull/410)
 
+##2.3.5
+- Fix an issue where inserting/deleting sections could lead to inconsistent supplementary element behavior. [Adlai Holler](https://github.com/Adlai-Holler)
+- Overhaul logging and add activity tracing support. [Adlai Holler](https://github.com/Adlai-Holler)
+
 ##2.3.4
 - [Yoga] Rewrite YOGA_TREE_CONTIGUOUS mode with improved behavior and cleaner integration [Scott Goodson](https://github.com/appleguy)
 - [ASTraitCollection] Convert ASPrimitiveTraitCollection from lock to atomic. [Scott Goodson](https://github.com/appleguy)
@@ -15,7 +19,6 @@
 - Migrated unit tests to OCMock 3.4 (from 2.2) and improved the multiplex image node tests. [Adlai Holler](https://github.com/Adlai-Holler)
 - Fix CollectionNode double-load issue. This should significantly improve performance in cases where a collection node has content immediately available on first layout i.e. not fetched from the network. [Adlai Holler](https://github.com/Adlai-Holler)
 - Overhaul layout flattening algorithm [Huy Nguyen](https://github.com/nguyenhuy) [#395](https://github.com/TextureGroup/Texture/pull/395).
-- Fix an issue where inserting/deleting sections could lead to inconsistent supplementary element behavior. [Adlai Holler](https://github.com/Adlai-Holler)
 
 ## 2.3.3
 - [ASTextKitFontSizeAdjuster] Replace use of NSAttributedString's boundingRectWithSize:options:context: with NSLayoutManager's boundingRectForGlyphRange:inTextContainer: [Ricky Cancro](https://github.com/rcancro)

Source/ASCellNode.mm

@@ -315,13 +315,13 @@ - (void)handleVisibilityChange:(BOOL)isVisible
     if (ip != nil) {
       [result addObject:@{ @"indexPath" : ip }];
     }
-    [result addObject:@{ @"collectionNode" : ASObjectDescriptionMakeTiny(owningNode) }];
+    [result addObject:@{ @"collectionNode" : owningNode }];
   } else if ([owningNode isKindOfClass:[ASTableNode class]]) {
     NSIndexPath *ip = [(ASTableNode *)owningNode indexPathForNode:self];
     if (ip != nil) {
       [result addObject:@{ @"indexPath" : ip }];
     }
-    [result addObject:@{ @"tableNode" : ASObjectDescriptionMakeTiny(owningNode) }];
+    [result addObject:@{ @"tableNode" : owningNode }];
 
   } else if ([scrollView isKindOfClass:[ASCollectionView class]]) {
     NSIndexPath *ip = [(ASCollectionView *)scrollView indexPathForNode:self];

Source/ASCollectionView.mm

@@ -800,6 +800,8 @@ - (void)beginUpdates
 
   if (_batchUpdateCount == 0) {
     _changeSet = [[_ASHierarchyChangeSet alloc] initWithOldData:[_dataController itemCountsFromDataSource]];
+    _changeSet.rootActivity = as_activity_create("Perform async collection update", AS_ACTIVITY_CURRENT, OS_ACTIVITY_FLAG_DEFAULT);
+    _changeSet.submitActivity = as_activity_create("Submit changes for collection update", _changeSet.rootActivity, OS_ACTIVITY_FLAG_DEFAULT);
   }
   _batchUpdateCount++;  
 }
@@ -817,6 +819,7 @@ - (void)endUpdatesAnimated:(BOOL)animated completion:(nullable void (^)(BOOL))co
 
   if (_batchUpdateCount == 0) {
     _ASHierarchyChangeSet *changeSet = _changeSet;
+
     // Nil out _changeSet before forwarding to _dataController to allow the change set to cause subsequent batch updates on the same run loop
     _changeSet = nil;
     changeSet.animated = animated;
@@ -828,8 +831,13 @@ - (void)performBatchAnimated:(BOOL)animated updates:(void (^)())updates completi
 {
   ASDisplayNodeAssertMainThread();
   [self beginUpdates];
-  if (updates) {
-    updates();
+  as_activity_scope(_changeSet.rootActivity);
+  {
+    // Only include client code in the submit activity, the rest just lives in the root activity. 
+    as_activity_scope(_changeSet.submitActivity);
+    if (updates) {
+      updates();
+    }
   }
   [self endUpdatesAnimated:animated completion:completion];
 }
@@ -1575,10 +1583,12 @@ - (void)_beginBatchFetchingIfNeededWithContentOffset:(CGPoint)contentOffset velo
 
 - (void)_beginBatchFetching
 {
+  as_activity_create_for_scope("Batch fetch for collection node");
   [_batchContext beginBatchFetching];
   if (_asyncDelegateFlags.collectionNodeWillBeginBatchFetch) {
     dispatch_async(dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0), ^{
       GET_COLLECTIONNODE_OR_RETURN(collectionNode, (void)0);
+      as_log_debug(ASCollectionLog(), "Beginning batch fetch for %@ with context %@", collectionNode, _batchContext);
       [_asyncDelegate collectionNode:collectionNode willBeginBatchFetchWithContext:_batchContext];
     });
   } else if (_asyncDelegateFlags.collectionViewWillBeginBatchFetch) {
@@ -1894,9 +1904,11 @@ - (void)rangeController:(ASRangeController *)rangeController didUpdateWithChange
   }
 
   ASPerformBlockWithoutAnimation(!changeSet.animated, ^{
-    if(changeSet.includesReloadData) {
+    as_activity_scope(as_activity_create("Commit collection update", changeSet.rootActivity, OS_ACTIVITY_FLAG_DEFAULT));
+    if (changeSet.includesReloadData) {
       _superIsPendingDataLoad = YES;
       [super reloadData];
+      as_log_debug(ASCollectionLog(), "Did reloadData %@", self.collectionNode);
       [changeSet executeCompletionHandlerWithFinished:YES];
     } else {
       [_layoutFacilitator collectionViewWillPerformBatchUpdates];
@@ -1933,13 +1945,17 @@ - (void)rangeController:(ASRangeController *)rangeController didUpdateWithChange
           numberOfUpdates++;
         }
       } completion:^(BOOL finished){
+        as_activity_scope(as_activity_create("Handle collection update completion", changeSet.rootActivity, OS_ACTIVITY_FLAG_DEFAULT));
+        as_log_verbose(ASCollectionLog(), "Update animation finished %{public}@", self.collectionNode);
         // Flush any range changes that happened as part of the update animations ending.
         [_rangeController updateIfNeeded];
         [self _scheduleCheckForBatchFetchingForNumberOfChanges:numberOfUpdates];
         [changeSet executeCompletionHandlerWithFinished:finished];
       }];
+      as_log_debug(ASCollectionLog(), "Completed batch update %{public}@", self.collectionNode);
 
       // Flush any range changes that happened as part of submitting the update.
+      as_activity_scope(changeSet.rootActivity);
       [_rangeController updateIfNeeded];
     }
   });

Source/ASDisplayNode+Layout.mm

@@ -15,6 +15,7 @@
 #import <AsyncDisplayKit/ASInternalHelpers.h>
 #import <AsyncDisplayKit/ASLayout.h>
 #import <AsyncDisplayKit/ASLayoutElementStylePrivate.h>
+#import <AsyncDisplayKit/ASLog.h>
 
 #import <AsyncDisplayKit/ASDisplayNode+FrameworkSubclasses.h>
 
@@ -127,25 +128,20 @@ - (ASTraitCollection *)asyncTraitCollection
 
 ASPrimitiveTraitCollectionDeprecatedImplementation
 
-@end
-
-#pragma mark -
 #pragma mark - ASLayoutElementAsciiArtProtocol
 
-@implementation ASDisplayNode (ASLayoutElementAsciiArtProtocol)
-
 - (NSString *)asciiArtString
 {
   return [ASLayoutSpec asciiArtStringForChildren:@[] parentName:[self asciiArtName]];
 }
 
 - (NSString *)asciiArtName
 {
-  NSString *string = NSStringFromClass([self class]);
+  NSMutableString *result = [NSMutableString stringWithCString:object_getClassName(self) encoding:NSASCIIStringEncoding];
   if (_debugName) {
-    string = [string stringByAppendingString:[NSString stringWithFormat:@"\"%@\"",_debugName]];
+    [result appendFormat:@" (%@)", _debugName];
   }
-  return string;
+  return result;
 }
 
 @end
@@ -222,6 +218,7 @@ @implementation ASDisplayNode (ASLayoutInternal)
  */
 - (void)_setNeedsLayoutFromAbove
 {
+  as_activity_create_for_scope("Set needs layout from above");
   ASDisplayNodeAssertThreadAffinity(self);
 
   // Mark the node for layout in the next layout pass
@@ -315,6 +312,8 @@ - (void)_locked_measureNodeWithBoundsIfNecessary:(CGRect)bounds
     }
   }
 
+  as_activity_create_for_scope("Update node layout for current bounds");
+  as_log_verbose(ASLayoutLog(), "Node %@, bounds size %@, calculatedSize %@, calculatedIsDirty %d", self, NSStringFromCGSize(boundsSizeForLayout), NSStringFromCGSize(_calculatedDisplayNodeLayout->layout.size), _calculatedDisplayNodeLayout->isDirty());
   // _calculatedDisplayNodeLayout is not reusable we need to transition to a new one
   [self cancelLayoutTransition];
 
@@ -332,7 +331,20 @@ - (void)_locked_measureNodeWithBoundsIfNecessary:(CGRect)bounds
 
   // nextLayout was likely created by a call to layoutThatFits:, check if it is valid and can be applied.
   // If our bounds size is different than it, or invalid, recalculate.  Use #define to avoid nullptr->
-  if (nextLayout == nullptr || nextLayout->isDirty() == YES || layoutSizeDifferentFromBounds) {
+  BOOL pendingLayoutApplicable = NO;
+  if (nextLayout == nullptr) {
+    as_log_verbose(ASLayoutLog(), "No pending layout.");
+  } else if (nextLayout->isDirty()) {
+    as_log_verbose(ASLayoutLog(), "Pending layout is invalid.");
+  } else if (layoutSizeDifferentFromBounds) {
+    as_log_verbose(ASLayoutLog(), "Pending layout size %@ doesn't match bounds size.", NSStringFromCGSize(nextLayout->layout.size));
+  } else {
+    as_log_verbose(ASLayoutLog(), "Using pending layout %@.", nextLayout->layout);
+    pendingLayoutApplicable = YES;
+  }
+
+  if (!pendingLayoutApplicable) {
+    as_log_verbose(ASLayoutLog(), "Measuring with previous constrained size.");
     // Use the last known constrainedSize passed from a parent during layout (if never, use bounds).
     ASSizeRange constrainedSize = [self _locked_constrainedSizeForLayoutPass];
     ASLayout *layout = [self calculateLayoutThatFits:constrainedSize
@@ -350,6 +362,7 @@ - (void)_locked_measureNodeWithBoundsIfNecessary:(CGRect)bounds
   // This can occur for either pre-calculated or newly-calculated layouts.
   if (nextLayout->requestedLayoutFromAbove == NO
       && CGSizeEqualToSize(boundsSizeForLayout, nextLayout->layout.size) == NO) {
+    as_log_verbose(ASLayoutLog(), "Layout size doesn't match bounds size. Requesting layout from above.");
     // The layout that we have specifies that this node (self) would like to be a different size
     // than it currently is.  Because that size has been computed within the constrainedSize, we
     // expect that calling setNeedsLayoutFromAbove will result in our parent resizing us to this.
@@ -506,10 +519,13 @@ - (void)transitionLayoutWithSizeRange:(ASSizeRange)constrainedSize
                 measurementCompletion:(void(^)())completion
 {
   ASDisplayNodeAssertMainThread();
+  as_activity_create_for_scope("Transition node layout");
+  as_log_debug(ASLayoutLog(), "Transition layout for %@ sizeRange %@ anim %d asyncMeasure %d", self, NSStringFromASSizeRange(constrainedSize), animated, shouldMeasureAsync);
 
   if (constrainedSize.max.width <= 0.0 || constrainedSize.max.height <= 0.0) {
     // Using CGSizeZero for the sizeRange can cause negative values in client layout code.
     // Most likely called transitionLayout: without providing a size, before first layout pass.
+    as_log_verbose(ASLayoutLog(), "Ignoring transition due to bad size range.");
     return;
   }
 
@@ -526,9 +542,14 @@ - (void)transitionLayoutWithSizeRange:(ASSizeRange)constrainedSize
 
   // Every new layout transition has a transition id associated to check in subsequent transitions for cancelling
   int32_t transitionID = [self _startNewTransition];
+  as_log_verbose(ASLayoutLog(), "Transition ID is %d", transitionID);
   // NOTE: This block captures self. It's cheaper than hitting the weak table.
   asdisplaynode_iscancelled_block_t isCancelled = ^{
-    return (BOOL)(_transitionID != transitionID);
+    BOOL result = (_transitionID != transitionID);
+    if (result) {
+      as_log_verbose(ASLayoutLog(), "Transition %d canceled, superseded by %d", transitionID, _transitionID.load());
+    }
+    return result;
   };
 
   // Move all subnodes in layout pending state for this transition
@@ -573,6 +594,7 @@ - (void)transitionLayoutWithSizeRange:(ASSizeRange)constrainedSize
       if (isCancelled()) {
         return;
       }
+      as_activity_create_for_scope("Commit layout transition");
       ASLayoutTransition *pendingLayoutTransition;
       _ASTransitionContext *pendingLayoutTransitionContext;
       {
@@ -598,10 +620,13 @@ - (void)transitionLayoutWithSizeRange:(ASSizeRange)constrainedSize
       }
 
       // Apply complete layout transitions for all subnodes
-      ASDisplayNodePerformBlockOnEverySubnode(self, NO, ^(ASDisplayNode * _Nonnull node) {
-        [node _completePendingLayoutTransition];
-        node.hierarchyState &= (~ASHierarchyStateLayoutPending);
-      });
+      {
+        as_activity_create_for_scope("Complete pending layout transitions for subtree");
+        ASDisplayNodePerformBlockOnEverySubnode(self, NO, ^(ASDisplayNode * _Nonnull node) {
+          [node _completePendingLayoutTransition];
+          node.hierarchyState &= (~ASHierarchyStateLayoutPending);
+        });
+      }
 
       // Measurement pass completion
       // Give the subclass a change to hook into before calling the completion block
@@ -614,7 +639,10 @@ - (void)transitionLayoutWithSizeRange:(ASSizeRange)constrainedSize
       [pendingLayoutTransition applySubnodeInsertions];
 
       // Kick off animating the layout transition
-      [self animateLayoutTransition:pendingLayoutTransitionContext];
+      {
+        as_activity_create_for_scope("Animate layout transition");
+        [self animateLayoutTransition:pendingLayoutTransitionContext];
+      }
 
       // Mark transaction as finished
       [self _finishOrCancelTransition];
@@ -805,7 +833,7 @@ - (void)_completePendingLayoutTransition
  */
 - (void)_completeLayoutTransition:(ASLayoutTransition *)layoutTransition
 {
-  // Layout transition is not supported for nodes that are not have automatic subnode management enabled
+  // Layout transition is not supported for nodes that do not have automatic subnode management enabled
   if (layoutTransition == nil || self.automaticallyManagesSubnodes == NO) {
     return;
   }

Source/ASDisplayNode+Subclasses.h

@@ -514,7 +514,7 @@ NS_ASSUME_NONNULL_BEGIN
 
 @end
 
-#define ASDisplayNodeAssertThreadAffinity(viewNode)   ASDisplayNodeAssert(!viewNode || ASDisplayNodeThreadIsMain() || !(viewNode).nodeLoaded, @"Incorrect display node thread affinity - this method should not be called off the main thread after the ASDisplayNode's view or layer have been created")
-#define ASDisplayNodeCAssertThreadAffinity(viewNode) ASDisplayNodeCAssert(!viewNode || ASDisplayNodeThreadIsMain() || !(viewNode).nodeLoaded, @"Incorrect display node thread affinity - this method should not be called off the main thread after the ASDisplayNode's view or layer have been created")
+#define ASDisplayNodeAssertThreadAffinity(viewNode)   ASDisplayNodeAssert(!viewNode || ASMainThreadAssertionsAreDisabled() || ASDisplayNodeThreadIsMain() || !(viewNode).nodeLoaded, @"Incorrect display node thread affinity - this method should not be called off the main thread after the ASDisplayNode's view or layer have been created")
+#define ASDisplayNodeCAssertThreadAffinity(viewNode) ASDisplayNodeCAssert(!viewNode || ASMainThreadAssertionsAreDisabled() || ASDisplayNodeThreadIsMain() || !(viewNode).nodeLoaded, @"Incorrect display node thread affinity - this method should not be called off the main thread after the ASDisplayNode's view or layer have been created")
 
 NS_ASSUME_NONNULL_END

Source/ASDisplayNode.h

@@ -748,9 +748,6 @@ extern NSInteger const ASDefaultDrawingPriority;
 
 @end
 
-@interface ASDisplayNode (ASLayoutElementAsciiArtProtocol) <ASLayoutElementAsciiArtProtocol>
-@end
-
 @interface ASDisplayNode (ASLayout)
 
 /** @name Managing dimensions */