Merge pull request #2622 from facebook/AHEventLoggingInProduction

[ASTraceEvent, Debugging] Greatly Improve Event Logging.

AsyncDisplayKit/ASDisplayNode.mm

@@ -307,7 +307,7 @@ static ASDisplayNodeMethodOverrides GetASDisplayNodeMethodOverrides(Class c)
   [self _staticInitialize];
 
 #if ASEVENTLOG_ENABLE
-  _eventLog = [[ASEventLog alloc] init];
+  _eventLog = [[ASEventLog alloc] initWithObject:self];
 #endif
   
   _contentsScaleForDisplay = ASScreenScale();

AsyncDisplayKit/Details/ASEventLog.h

@@ -15,15 +15,24 @@
 #endif
 
 #ifndef ASEVENTLOG_ENABLE
-#define ASEVENTLOG_ENABLE 1
+#define ASEVENTLOG_ENABLE DEBUG
 #endif
 
 NS_ASSUME_NONNULL_BEGIN
 
 @interface ASEventLog : NSObject
 
+/**
+ * Create a new event log.
+ *
+ * @param anObject The object whose events we are logging. This object is not retained.
+ */
+- (instancetype)initWithObject:(id)anObject;
+
 - (void)logEventWithBacktrace:(nullable NSArray<NSString *> *)backtrace format:(NSString *)format, ... NS_FORMAT_FUNCTION(2, 3);
 
+- (instancetype)init NS_UNAVAILABLE;
+
 @end
 
 NS_ASSUME_NONNULL_END

AsyncDisplayKit/Details/ASEventLog.mm

@@ -13,57 +13,86 @@
 #import "ASEventLog.h"
 #import "ASThread.h"
 #import "ASTraceEvent.h"
+#import "ASObjectDescriptionHelpers.h"
 
-@interface ASEventLog ()
-{
+@implementation ASEventLog {
   ASDN::RecursiveMutex __instanceLock__;
+
   // The index of the most recent log entry. -1 until first entry.
   NSInteger _eventLogHead;
-  // The most recent trace events. Max count is ASEVENTLOG_CAPACITY.
-  NSMutableArray<ASTraceEvent *> *_eventLog;
+
+  // A description of the object we're logging for. This is immutable.
+  NSString *_objectDescription;
 }
-@end
 
-@implementation ASEventLog
+/**
+ * Even just when debugging, all these events can take up considerable memory.
+ * Store them in a shared NSCache to limit the total consumption.
+ */
++ (NSCache<ASEventLog *, NSMutableArray<ASTraceEvent *> *> *)contentsCache
+{
+  static NSCache *cache;
+  static dispatch_once_t onceToken;
+  dispatch_once(&onceToken, ^{
+    cache = [[NSCache alloc] init];
+  });
+  return cache;
+}
 
-- (instancetype)init
+- (instancetype)initWithObject:(id)anObject
 {
   if ((self = [super init])) {
+    _objectDescription = ASObjectDescriptionMakeTiny(anObject);
     _eventLogHead = -1;
   }
   return self;
 }
 
+- (instancetype)init
+{
+  // This method is marked unavailable so the compiler won't let them call it.
+  ASDisplayNodeFailAssert(@"Failed to call initWithObject:");
+  return nil;
+}
+
 - (void)logEventWithBacktrace:(NSArray<NSString *> *)backtrace format:(NSString *)format, ...
 {
   va_list args;
   va_start(args, format);
-  ASTraceEvent *event = [[ASTraceEvent alloc] initWithObject:self
-                                                   backtrace:backtrace
-                                                      format:format
-                                                   arguments:args];
+  ASTraceEvent *event = [[ASTraceEvent alloc] initWithBacktrace:backtrace
+                                                         format:format
+                                                      arguments:args];
   va_end(args);
-  
+
   ASDN::MutexLocker l(__instanceLock__);
-  // Create the array if needed.
-  if (_eventLog == nil) {
-    _eventLog = [NSMutableArray arrayWithCapacity:ASEVENTLOG_CAPACITY];
+  NSCache *cache = [ASEventLog contentsCache];
+  NSMutableArray<ASTraceEvent *> *events = [cache objectForKey:self];
+  if (events == nil) {
+    events = [NSMutableArray arrayWithObject:event];
+    [cache setObject:events forKey:self];
+    _eventLogHead = 0;
+    return;
   }
-  
+
   // Increment the head index.
   _eventLogHead = (_eventLogHead + 1) % ASEVENTLOG_CAPACITY;
-  if (_eventLogHead < _eventLog.count) {
-    [_eventLog replaceObjectAtIndex:_eventLogHead withObject:event];
+  if (_eventLogHead < events.count) {
+    [events replaceObjectAtIndex:_eventLogHead withObject:event];
   } else {
-    [_eventLog insertObject:event atIndex:_eventLogHead];
+    [events insertObject:event atIndex:_eventLogHead];
   }
 }
 
-- (NSArray<ASTraceEvent *> *)eventLog
+- (NSArray<ASTraceEvent *> *)events
 {
+  NSMutableArray<ASTraceEvent *> *events = [[ASEventLog contentsCache] objectForKey:self];
+  if (events == nil) {
+    return nil;
+  }
+
   ASDN::MutexLocker l(__instanceLock__);
   NSUInteger tail = (_eventLogHead + 1);
-  NSUInteger count = _eventLog.count;
+  NSUInteger count = events.count;
   
   NSMutableArray<ASTraceEvent *> *result = [NSMutableArray array];
   
@@ -71,10 +100,25 @@
   for (NSUInteger actualIndex = 0; actualIndex < ASEVENTLOG_CAPACITY; actualIndex++) {
     NSInteger ringIndex = (tail + actualIndex) % ASEVENTLOG_CAPACITY;
     if (ringIndex < count) {
-      [result addObject:_eventLog[ringIndex]];
+      [result addObject:events[ringIndex]];
     }
   }
   return result;
 }
 
+- (NSString *)description
+{
+  /**
+   * This description intentionally doesn't follow the standard description format.
+   * Since this is a log, it's important for the description to look a certain way, and
+   * the formal description style doesn't allow for newlines and has a ton of punctuation.
+   */
+  NSArray *events = [self events];
+  if (events == nil) {
+    return [NSString stringWithFormat:@"Event log for %@ was purged to conserve memory.", _objectDescription];
+  } else {
+    return [NSString stringWithFormat:@"Event log for %@. Events: %@", _objectDescription, events];
+  }
+}
+
 @end

AsyncDisplayKit/Details/ASTraceEvent.h

@@ -15,10 +15,9 @@ NS_ASSUME_NONNULL_BEGIN
 /**
  * This method is dealloc safe.
  */
-- (instancetype)initWithObject:(id)object
-                     backtrace:(nullable NSArray<NSString *> *)backtrace
-                        format:(NSString *)format
-                     arguments:(va_list)arguments NS_FORMAT_FUNCTION(3,0);
+- (instancetype)initWithBacktrace:(nullable NSArray<NSString *> *)backtrace
+                           format:(NSString *)format
+                        arguments:(va_list)arguments NS_FORMAT_FUNCTION(2,0);
 
 // Will be nil unless AS_SAVE_EVENT_BACKTRACES=1 (default=0)
 @property (nonatomic, nullable, readonly) NSArray<NSString *> *backtrace;

AsyncDisplayKit/Details/ASTraceEvent.m

@@ -8,7 +8,8 @@
 
 #import "ASTraceEvent.h"
 #import <QuartzCore/QuartzCore.h>
-#import "ASObjectDescriptionHelpers.h"
+
+static NSString *const ASTraceEventThreadDescriptionKey = @"ASThreadTraceEventDescription";
 
 @interface ASTraceEvent ()
 @property (nonatomic, strong, readonly) NSString *objectDescription;
@@ -17,7 +18,7 @@
 
 @implementation ASTraceEvent
 
-- (instancetype)initWithObject:(id)object backtrace:(NSArray<NSString *> *)backtrace format:(NSString *)format arguments:(va_list)args
+- (instancetype)initWithBacktrace:(NSArray<NSString *> *)backtrace format:(NSString *)format arguments:(va_list)args
 {
   self = [super init];
   if (self != nil) {
@@ -29,8 +30,6 @@
     
     // Create the format string passed to us.
     _message = [[NSString alloc] initWithFormat:format arguments:args];
-    
-    _objectDescription = ASObjectDescriptionMakeTiny(object);
 	  
     NSThread *thread = [NSThread currentThread];
     NSString *threadDescription = thread.name;
@@ -38,10 +37,17 @@
       if ([thread isMainThread]) {
         threadDescription = @"Main";
       } else {
-        // Want these to be 4-chars to line up with "Main". It's possible that a collision could happen
-        // here but it's so unbelievably likely to impact development, the risk is acceptable.
-        NSString *ptrString = [NSString stringWithFormat:@"%p", thread];
-        threadDescription = [ptrString substringFromIndex:MAX(0, ptrString.length - 4)];
+        // If the bg thread has no name, we cache a 4-character ptr string to identify it by
+        // inside the thread dictionary.
+        NSMutableDictionary *threadDict = thread.threadDictionary;
+        threadDescription = threadDict[ASTraceEventThreadDescriptionKey];
+        if (threadDescription == nil) {
+          // Want these to be 4-chars to line up with "Main". It's possible that a collision could happen
+          // here but it's so unbelievably likely to impact development, the risk is acceptable.
+          NSString *ptrString = [NSString stringWithFormat:@"%p", thread];
+          threadDescription = [ptrString substringFromIndex:MAX(0, ptrString.length - 4)];
+          threadDict[ASTraceEventThreadDescriptionKey] = threadDescription;
+        }
       }
     }
     _threadDescription = threadDescription;
@@ -54,7 +60,7 @@
 
 - (NSString *)description
 {
-  return [NSString stringWithFormat:@"<%@ (%@) t=%7.3f: %@>", _objectDescription, _threadDescription, _timestamp, _message];
+  return [NSString stringWithFormat:@"<(%@) t=%7.3f: %@>", _threadDescription, _timestamp, _message];
 }
 
 @end

AsyncDisplayKitTests/ASTableViewTests.m

@@ -54,7 +54,7 @@
 - (instancetype)__initWithFrame:(CGRect)frame style:(UITableViewStyle)style
 {
   
-  return [super _initWithFrame:frame style:style dataControllerClass:[ASTestDataController class] eventLog:[[ASEventLog alloc] init]];
+  return [super _initWithFrame:frame style:style dataControllerClass:[ASTestDataController class] eventLog:nil];
 }
 
 - (ASTestDataController *)testDataController