Overhaul our logging, add activity tracing support. #399

Adlai-Holler · 2017-06-29T03:46:37Z

In iOS 10, the kernel logging and activity tracing frameworks were unified together. Check out this WWDC talk for a full run-through of what that means, but it's pretty powerful https://developer.apple.com/videos/play/wwdc2016/721/ .

Short video demo of the verbose level on a cold launch of the Pinterest iOS app.
https://youtu.be/e392CekeH4c EDIT: another demo https://youtu.be/H_P5nCFlPYM

This diff creates several different logs, and it adds a new level verbose in addition to the system levels info, debug, fault, error. We should feel free to add new logs in the future because these things are fast and very easy to disable.

/// Log for general node-specific events e.g. interfaceState (for root nodes).
os_log_t ASNodeLog();
/// Log for layout-specific events e.g. calculateLayout (for root nodes).
os_log_t ASLayoutLog();
/// Log for display-specific events e.g. display queue batches.
os_log_t ASRenderLog();
/// Log for collection node events e.g. performBatchUpdates.
os_log_t ASCollectionLog();
/// Log for ASNetworkImageNode and ASMultiplexImageNode
os_log_t ASImageLoadingLog();
/// Specialized log for our main thread deallocation system.
os_log_t ASMainThreadDeallocationLog();

The default log level is intended to be quiet enough that users don't turn it off. Currently includes:

Activities and logs for all calls to transitionLayoutWithSizeRange. @nguyenhuy it could be beneficial to add more logs in here, probably at the verbose level.
Activities and logs for all collection initial load/reloadData/performBatchUpdates.
Activities and logs for all collection node batch fetching.
Activities and logs for ASNavigationController and ASTabBarController operations.
Activities and logs for trait collection propagation.
Activities and logs for transitionLayoutWithAnimation:.

The verbose log level is a free-for-all. We should feel free to dump more and more content in there to our heart's content. Currently includes:

Logs and activities for calls to [ASDisplayNode calculateLayoutThatFits:], along with ASCII art for the layout spec.
Activities for all range controller updates.
Activities for all data controller cell allocation batches.
Activities for all calls to -recursivelySetInterfaceState:
Logs for all node interface state changes.
Logs for all node didLoad events.
Logs for all ASNetworkImageNode/ASMultiplexImageNode events.
Logs for addSubnode/removeFromSupernode.

Requirements

For activity tracing, Texture's deployment target must be raised to 10.0.
- Easiest way is to go to the Pods project of your Xcode workspace, select the Texture target and under Build settings raise iOS Deployment Target to 10.0.
- The tracing API in 9.0 is very different, and it's incompatible with the unified system so we don't use it.
To use Console.app, you have to use a real device not simulator. The simulator and Console.app are supposed to work together, but on my computers they interfere and the simulator dies.
In Console.app, check "Include debug messages" and "Include info messages"

Recommendations

Set debugName and/or accessibilityIdentifiers! These help tremendously with identifying nodes. You can use the ASSetDebugName macro to conditionally set the debug name if you're in DEBUG and skip it in production.
Filter by library:UIKit and library:MyApp to hide log messages from Security, CoreFoundation, and other system frameworks you probably don't care about.
Filter by process e.g. process:Pinterest. You can also filter by PID for each run of your process if you want.
Save your common search terms (see screenshot below) so you can quickly jump to them.
Show the PID: ThreadID filed in the results view. This field is pretty worthwhile.
Get used to the difference between the Activities view and the default view.
- For instance, if you're looking for info about <ASDisplayNode: 0xFFFFFFFF>, you can leave the Activities view, then search for 0xFFFFFFFF, then read the Activity ID 12345 of the log message you're interested in, then use that as a search term.

Pretty pictures:

appleguy · 2017-07-02T20:05:39Z

@Adlai-Holler fixed up the two merge conflicts. I'll try to get this reviewed in the next hour.

appleguy

This is like the god-diff of logging! Holy wow.

All of my comments are questions or suggestions, so I think it would be a good idea to land this and address them separately.

I will say that this adds a nontrivial amount of complexity to some of our denser areas of the code. The value proposition is unquestionable - it's worth that cost - but it would also be worth imagining if there are ways (through denser macros or other wrappers) that can make the logging hints lighter weight visually.

One way to do that would be for the invocation to be as short as possible and really lead with the log message, to have them serve as comments, and put everything else in arguments later in the call.

appleguy · 2017-07-02T20:32:22Z

Source/ASCellNode.mm

@@ -315,13 +315,13 @@ - (void)handleVisibilityChange:(BOOL)isVisible
    if (ip != nil) {
      [result addObject:@{ @"indexPath" : ip }];
    }
-    [result addObject:@{ @"collectionNode" : ASObjectDescriptionMakeTiny(owningNode) }];


Longer term, I wonder if a separate file like ASLog+DebugDescriptions.m would be a good place to locate category implementations for all the node classes. One-stop shop for logging contents with helper macros and such. Locating it in the class like this might be better for other reasons, though.

appleguy · 2017-07-02T20:34:20Z

Source/ASCollectionView.mm

@@ -828,8 +831,12 @@ - (void)performBatchAnimated:(BOOL)animated updates:(void (^)())updates completi
 {
  ASDisplayNodeAssertMainThread();
  [self beginUpdates];
-  if (updates) {
-    updates();
+  as_activity_scope(_changeSet.rootActivity);


Maybe worth a comment - I don't really understand what this anonymous scope is doing (I think it is only containing the submitActivity, but why is the rootActivity started right above the anonymous scope rather than at the top of the method?)

appleguy · 2017-07-02T20:35:27Z

Source/ASCollectionView.mm

@@ -1575,10 +1582,12 @@ - (void)_beginBatchFetchingIfNeededWithContentOffset:(CGPoint)contentOffset velo

 - (void)_beginBatchFetching
 {
+  as_activity_scope(as_activity_create("Batch fetch for collection node", AS_ACTIVITY_CURRENT, OS_ACTIVITY_FLAG_DEFAULT));


Should we offer as_activity_scope_create() for one level of parentheses?

Also worth to use AS_ACTIVITY_CURRENT and OS_ACTIVITY_FLAG_DEFAULT as default values as well.

appleguy · 2017-07-02T20:37:30Z

Source/ASDisplayNode+Layout.mm

 - (NSString *)asciiArtString
 {
  return [ASLayoutSpec asciiArtStringForChildren:@[] parentName:[self asciiArtName]];
 }

 - (NSString *)asciiArtName
 {
-  NSString *string = NSStringFromClass([self class]);
+  NSMutableString *result = [NSMutableString stringWithCString:object_getClassName(self) encoding:NSASCIIStringEncoding];


This is interesting - it seems plausible to be faster, but is that indeed the reason you changed this?

Yes I wanted to reduce the number of strings created from 3 to 1. Digging into the current implementation of NSStringFromClass shows that it always creates a new instance of NSString.

appleguy · 2017-07-02T20:40:43Z

Source/ASDisplayNode.mm

@@ -1304,6 +1310,7 @@ + (void)scheduleNodeForRecursiveDisplay:(ASDisplayNode *)node
    }];
  });

+  as_log_verbose(ASRenderLog(), "%s %@", sel_getName(_cmd), node);


I think ASDisplayLog might be a better name for this, as we've standardized on Display Range, recursivelyEnsureDisplay, setNeedsDisplay, etc. There are some stragglers like renderQueue here though, and I realize ASDisplay looks a bit like ASDisplayNode, so you can decide.

appleguy · 2017-07-02T20:43:10Z

Source/ASDisplayNode.mm

@@ -2331,6 +2339,11 @@ - (void)_removeFromSupernodeIfEqualTo:(ASDisplayNode *)supernode

 - (void)_removeFromSupernode:(ASDisplayNode *)supernode view:(UIView *)view layer:(CALayer *)layer
 {
+  // TODO: Should we simply return early if supernode is nil? This currently gets called for every insertSubnode.


The answer to this is probably no, because it is possible to have the _view / _layer be in a parent without having a supernode. I've fixed some bugs related to that before: specifically addSubnode: category exists on UIView, but when you perform that and there's no associated node, then removeFromSupernode did not remove it from the view (so it had assymetric behavior).

In that sense I think this is correct, so you can remove the TODO and optionally comment as to why we do this.

appleguy · 2017-07-02T20:44:41Z

Source/ASDisplayNode.mm

-  ASDisplayNodeLogEvent(self, @"interfaceStateDidChange: %@, old: %@", NSStringFromASInterfaceState(newState), NSStringFromASInterfaceState(oldState));
+  // Log this change, unless it's just the node going from {} -> {Measure} because that change happens
+  // for all cell nodes and it isn't currently meaningful.
+  BOOL isJustEnteringMeasure = (oldState == ASInterfaceStateNone && newState == ASInterfaceStateMeasureLayout);


Is the better way to check this, old | new == MeasureLayout ?

appleguy · 2017-07-02T20:45:56Z

Source/ASDisplayNode.mm

@@ -3179,7 +3211,10 @@ - (ASEventLog *)eventLog
  if (self.debugName.length > 0) {
    [result addObject:@{ @"debugName" : ASStringWithQuotesIfMultiword(self.debugName)}];
  }
-
+  if (self.accessibilityIdentifier.length > 0) {
+    [result addObject:@{ @"axId": ASStringWithQuotesIfMultiword(self.accessibilityIdentifier) }];


Why does this use axId but above, the axId is set to kCFNull? Worth a comment in the kCFNull case as to why that is the key for the dictionary.

Since this is the -debugDescription we can afford to be more verbose. The difference in output string is:

<MYNode: 0x00000001; axId = "Like button"> vs. <MYNode: 0x00000001; "Like button">

I'll find some way to expose this behavior more clearly in headers/comments.

appleguy · 2017-07-02T20:46:37Z

Source/ASDisplayNodeExtras.h

+  } \
+})
+
+/// e.g. { +Visible, -Preload } (although that should never actually happen.)


This is a great way to communicate interface state changes!

appleguy · 2017-07-02T20:48:15Z

Source/Base/ASLog.m

+os_log_t ASRenderLog() {
+  static os_log_t log;
+#if ASEnableLogs && ASRenderLogEnabled
+  static dispatch_once_t onceToken;


This is totally ripe for ASCreateOnce() plsy pls

nguyenhuy

This is really cool indeed! Nits aside, LGTM!

nguyenhuy · 2017-07-03T13:30:19Z

Source/ASCollectionView.mm

@@ -1575,10 +1582,12 @@ - (void)_beginBatchFetchingIfNeededWithContentOffset:(CGPoint)contentOffset velo

 - (void)_beginBatchFetching
 {
+  as_activity_scope(as_activity_create("Batch fetch for collection node", AS_ACTIVITY_CURRENT, OS_ACTIVITY_FLAG_DEFAULT));


Also worth to use AS_ACTIVITY_CURRENT and OS_ACTIVITY_FLAG_DEFAULT as default values as well.

nguyenhuy · 2017-07-03T13:37:36Z

Source/ASDisplayNode.mm

@@ -3166,9 +3188,19 @@ - (ASEventLog *)eventLog
 - (NSMutableArray<NSDictionary *> *)propertiesForDescription
 {
  NSMutableArray<NSDictionary *> *result = [NSMutableArray array];
-  if (self.debugName.length > 0) {
-    [result addObject:@{ @"debugName" : ASStringWithQuotesIfMultiword(self.debugName) }];
+  ASPushMainThreadAssertionsDisabled();


nguyenhuy · 2017-07-03T14:01:32Z

Source/Base/ASSignpost.h

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


What's up with the indentations above? Tabs?

nguyenhuy · 2017-07-03T14:04:11Z

Source/Details/ASDataController.mm

@@ -547,27 +562,36 @@ - (void)updateWithChangeSet:(_ASHierarchyChangeSet *)changeSet
  }

  // Mutable copy of current data.


This comment is in a wrong place now. Please move it down or remove it.

nguyenhuy · 2017-07-03T14:33:01Z

Source/ASNetworkImageNode.mm

    downloadIdentifier = [_downloader downloadImageWithURL:url
                                             callbackQueue:dispatch_get_main_queue()
                                          downloadProgress:NULL
                                                completion:^(id <ASImageContainerProtocol> _Nullable imageContainer, NSError * _Nullable error, id  _Nullable downloadIdentifier) {
+                                                  as_log_verbose(ASImageLoadingLog(), "Downloaded image for %@ img: %@ url: %@", self, [imageContainer asdk_image], url);


Should we weakify/strongify here?

Good call, I moved the log into the completion block since it's always static.

appleguy · 2017-07-03T21:03:00Z

Source/Base/ASLog.m

+#import <AsyncDisplayKit/ASLog.h>
+
+os_log_t ASNodeLog() {
+  static os_log_t log;


Doesn't this need to be initialized to some blank / NULL value in the case that the compile time gating is turned off?

Adlai-Holler · 2017-07-04T00:28:25Z

Thanks bros for the feedback, it's in much better shape now and I'll land post-CI.

ghost · 2017-07-04T00:29:02Z

	1 Warning
⚠️	This is a big PR, please consider splitting it up to ease code review.

Generated by 🚫 Danger

* Improve the os_log and os_activity integration * Address feedback from Scott and Huy

Adlai-Holler added the Debuggability label Jun 29, 2017

Adlai-Holler force-pushed the AHBetterLogging branch 11 times, most recently from 41a4baf to aa503ca Compare June 30, 2017 01:42

TextureGroup deleted a comment Jun 30, 2017

Adlai-Holler requested review from maicki, garrettmoon, appleguy and nguyenhuy June 30, 2017 01:56

Adlai-Holler force-pushed the AHBetterLogging branch from 7dd3778 to 0a1c468 Compare June 30, 2017 02:10

TextureGroup deleted a comment Jun 30, 2017

Improve the os_log and os_activity integration

7aaf3f1

Adlai-Holler force-pushed the AHBetterLogging branch from a0ffc9e to 7aaf3f1 Compare June 30, 2017 18:00

Adlai-Holler mentioned this pull request Jul 2, 2017

[Yoga] Refine the handling of measurement functions when Yoga is used. #408

Merged

Merge branch 'master' into AHBetterLogging

118ac54

appleguy approved these changes Jul 2, 2017

View reviewed changes

nguyenhuy approved these changes Jul 3, 2017

View reviewed changes

appleguy reviewed Jul 3, 2017

View reviewed changes

Address feedback from Scott and Huy

ed035ee

Adlai-Holler merged commit 8ec4b31 into master Jul 4, 2017

Adlai-Holler deleted the AHBetterLogging branch July 4, 2017 02:03

bernieperez pushed a commit to AtomTickets/Texture that referenced this pull request Apr 25, 2018

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

b68a3b5

* Improve the os_log and os_activity integration * Address feedback from Scott and Huy

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Overhaul our logging, add activity tracing support. #399

Overhaul our logging, add activity tracing support. #399

Adlai-Holler commented Jun 29, 2017 •

edited

Loading

appleguy commented Jul 2, 2017

appleguy left a comment

appleguy Jul 2, 2017

appleguy Jul 2, 2017

appleguy Jul 2, 2017

nguyenhuy Jul 3, 2017

appleguy Jul 2, 2017

Adlai-Holler Jul 2, 2017 •

edited

Loading

appleguy Jul 2, 2017

appleguy Jul 2, 2017

appleguy Jul 2, 2017

appleguy Jul 2, 2017

Adlai-Holler Jul 2, 2017

appleguy Jul 2, 2017

appleguy Jul 2, 2017

nguyenhuy left a comment

nguyenhuy Jul 3, 2017

nguyenhuy Jul 3, 2017

nguyenhuy Jul 3, 2017

nguyenhuy Jul 3, 2017

nguyenhuy Jul 3, 2017

Adlai-Holler Jul 4, 2017

appleguy Jul 3, 2017

Adlai-Holler commented Jul 4, 2017

ghost commented Jul 4, 2017

		@@ -547,27 +562,36 @@ - (void)updateWithChangeSet:(_ASHierarchyChangeSet *)changeSet
		}

		// Mutable copy of current data.

Overhaul our logging, add activity tracing support. #399

Overhaul our logging, add activity tracing support. #399

Conversation

Adlai-Holler commented Jun 29, 2017 • edited Loading

Requirements

Recommendations

appleguy commented Jul 2, 2017

appleguy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Adlai-Holler Jul 2, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nguyenhuy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Adlai-Holler commented Jul 4, 2017

ghost commented Jul 4, 2017

Adlai-Holler commented Jun 29, 2017 •

edited

Loading

Adlai-Holler Jul 2, 2017 •

edited

Loading