From 4a48ba8be2464982a26f90e1548e47e437e82a00 Mon Sep 17 00:00:00 2001 From: Adlai Holler Date: Thu, 17 Nov 2016 11:51:35 +0900 Subject: [PATCH] Improve our event logging greatly --- AsyncDisplayKit/ASDisplayNode.mm | 2 +- AsyncDisplayKit/Details/ASEventLog.h | 11 +++- AsyncDisplayKit/Details/ASEventLog.mm | 88 ++++++++++++++++++------- AsyncDisplayKit/Details/ASTraceEvent.h | 7 +- AsyncDisplayKit/Details/ASTraceEvent.m | 24 ++++--- AsyncDisplayKitTests/ASTableViewTests.m | 2 +- 6 files changed, 96 insertions(+), 38 deletions(-) diff --git a/AsyncDisplayKit/ASDisplayNode.mm b/AsyncDisplayKit/ASDisplayNode.mm index 29a0a5011d..22930f7d77 100644 --- a/AsyncDisplayKit/ASDisplayNode.mm +++ b/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(); diff --git a/AsyncDisplayKit/Details/ASEventLog.h b/AsyncDisplayKit/Details/ASEventLog.h index 95c2fb0f59..1e10193c62 100644 --- a/AsyncDisplayKit/Details/ASEventLog.h +++ b/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 *)backtrace format:(NSString *)format, ... NS_FORMAT_FUNCTION(2, 3); +- (instancetype)init NS_UNAVAILABLE; + @end NS_ASSUME_NONNULL_END diff --git a/AsyncDisplayKit/Details/ASEventLog.mm b/AsyncDisplayKit/Details/ASEventLog.mm index b94ea1b494..1cd5264680 100644 --- a/AsyncDisplayKit/Details/ASEventLog.mm +++ b/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 *_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 *> *)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 *)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 *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 *)eventLog +- (NSArray *)events { + NSMutableArray *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 *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 diff --git a/AsyncDisplayKit/Details/ASTraceEvent.h b/AsyncDisplayKit/Details/ASTraceEvent.h index 22267fafa2..5c77e418c7 100644 --- a/AsyncDisplayKit/Details/ASTraceEvent.h +++ b/AsyncDisplayKit/Details/ASTraceEvent.h @@ -15,10 +15,9 @@ NS_ASSUME_NONNULL_BEGIN /** * This method is dealloc safe. */ -- (instancetype)initWithObject:(id)object - backtrace:(nullable NSArray *)backtrace - format:(NSString *)format - arguments:(va_list)arguments NS_FORMAT_FUNCTION(3,0); +- (instancetype)initWithBacktrace:(nullable NSArray *)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 *backtrace; diff --git a/AsyncDisplayKit/Details/ASTraceEvent.m b/AsyncDisplayKit/Details/ASTraceEvent.m index 598cbeea21..85ff69ed0d 100644 --- a/AsyncDisplayKit/Details/ASTraceEvent.m +++ b/AsyncDisplayKit/Details/ASTraceEvent.m @@ -8,7 +8,8 @@ #import "ASTraceEvent.h" #import -#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 *)backtrace format:(NSString *)format arguments:(va_list)args +- (instancetype)initWithBacktrace:(NSArray *)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 diff --git a/AsyncDisplayKitTests/ASTableViewTests.m b/AsyncDisplayKitTests/ASTableViewTests.m index 0a1053b5b6..14a62bb0f5 100644 --- a/AsyncDisplayKitTests/ASTableViewTests.m +++ b/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