Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve System Trace Implementation #trivial #368

Merged
merged 6 commits into from
Jun 19, 2017
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Binary file added InstrumentsTemplates/SystemTrace.tracetemplate
Binary file not shown.
22 changes: 21 additions & 1 deletion Source/ASDisplayNode.mm
Original file line number Diff line number Diff line change
Expand Up @@ -948,9 +948,29 @@ - (ASLayout *)calculateLayoutThatFits:(ASSizeRange)constrainedSize
restrictedToSize:(ASLayoutElementSize)size
relativeToParentSize:(CGSize)parentSize
{
// Use a pthread specific to mark when this method is called re-entrant on same thread.
// We only want one calculateLayout signpost interval per thread.
// This is fast enough to do it unconditionally.
static pthread_key_t calculateLayoutKey;
static dispatch_once_t onceToken;
dispatch_once(&onceToken, ^{
pthread_key_create(&calculateLayoutKey, NULL);
});
BOOL isNested = pthread_getspecific(calculateLayoutKey) != NULL;
if (!isNested) {
pthread_setspecific(calculateLayoutKey, kCFBooleanTrue);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Adlai-Holler This is quite a bit of code to add to a core method like this; what do you think about simplifying the operation with a #define? There are at least two good options:

  • Create a generic macro for manufacturing dispatch_once variables; I use the one below, for example.
  • Better, especially if we need to check for nesting elsewhere: add to the macro and perform the "checkAndSet" together. Macro would return the previous value while setting it if unset, and then you could write if (...CheckAndSet) { ...SignpostStart... }
#define ASCreateOnce(expr) ({ \
  static dispatch_once_t onceToken; \
  static __typeof__(expr) staticVar; \
  dispatch_once(&onceToken, ^{ \
    staticVar = expr; \
  }); \
  staticVar; \
})

e.g. in usage,

static pthread_key_t calculateLayoutKey = ASCreateOnce(pthread_key_create(&calculateLayoutKey, NULL));

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point, thanks. To split the difference, I created a ASPthreadStaticKey(dtor) macro that lets you easily create a static pthread_key_t with a given destructor, and used it here. The general CreateOnce macro is great but I wanted something more specialized for this.

ASProfilingSignpostStart(ASSignpostCalculateLayout, self, 0);
}

ASSizeRange styleAndParentSize = ASLayoutElementSizeResolve(self.style.size, parentSize);
const ASSizeRange resolvedRange = ASSizeRangeIntersect(constrainedSize, styleAndParentSize);
return [self calculateLayoutThatFits:resolvedRange];
ASLayout *result = [self calculateLayoutThatFits:resolvedRange];

if (!isNested) {
pthread_setspecific(calculateLayoutKey, NULL);
ASProfilingSignpostEnd(ASSignpostCalculateLayout, self, 0, ASSignpostColorDefault);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if a higher-level version of this with fewer arguments would be warranted; ColorDefault is often used and the colors could be applied elsewhere as a mapping to the signpost type. A higher-level macro could also automatically capture the self pointer, and the signpost "routing layer" could choose to use it or not.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good call. I've renamed ASProfilingSignpost* -> ASSignpost*, and replaced ASSignpostStart[4] with ASSignpostStartCustom[4] and added ASSignpostStart1. Same for end.

}
return result;
}

- (ASLayout *)calculateLayoutThatFits:(ASSizeRange)constrainedSize
Expand Down
58 changes: 56 additions & 2 deletions Source/ASRunLoopQueue.mm
Original file line number Diff line number Diff line change
Expand Up @@ -78,16 +78,20 @@ - (void)threadMain
return;
}
// The scope below is entered while already locked. @autorelease is crucial here; see PR 2890.
NSInteger count;
@autoreleasepool {
#if ASRunLoopQueueLoggingEnabled
NSLog(@"ASDeallocQueue Processing: %lu objects destroyed", weakSelf->_queue.size());
#endif
// Sometimes we release 10,000 objects at a time. Don't hold the lock while releasing.
std::deque<id> currentQueue = weakSelf->_queue;
count = currentQueue.size();
ASProfilingSignpostStart(ASSignpostDeallocQueueDrain, count, 0);
weakSelf->_queue = std::deque<id>();
weakSelf->_queueLock.unlock();
currentQueue.clear();
}
ASProfilingSignpostEnd(ASSignpostDeallocQueueDrain, count, 0, ASSignpostColorDefault);
});

CFRunLoopRef runloop = CFRunLoopGetCurrent();
Expand Down Expand Up @@ -196,8 +200,58 @@ @interface ASRunLoopQueue () {

@end

#if AS_KDEBUG_ENABLE
typedef enum {
kCATransactionPhasePreLayout,
kCATransactionPhasePreCommit,
kCATransactionPhasePostCommit,
} CATransactionPhase;

@interface CATransaction (Private)
+ (void)addCommitHandler:(void(^)(void))block forPhase:(CATransactionPhase)phase;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Interesting, is this a real API? I didn't see it implemented in this patch. Given the compile-time gating, seems like a great thing to use.

Even though debug-only, since this could change in any iOS version (or maybe even doesn't exist on one of the older versions), it's worth adding an early-return to the registerObservers method checking [CALayer respondsToSelector:].

+ (int)currentState;
@end
#endif

@implementation ASRunLoopQueue

#if AS_KDEBUG_ENABLE
+ (void)load
{
[self registerCATransactionObservers];
}

+ (void)registerCATransactionObservers
{
static dispatch_block_t preLayoutHandler;
static dispatch_block_t preCommitHandler;
static dispatch_block_t postCommitHandler;
static dispatch_once_t onceToken;
dispatch_once(&onceToken, ^{
preLayoutHandler = ^{
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A possible style here would be:

static dispatch_block_t preLayoutHandler = ASCreateOnce(^{
  ASProfilingSignpostStart(ASSignpostCATransactionLayout, 0, [CATransaction currentState]);
});

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the look of this but you can't put breakpoints inside macros unfortunately, so I kept the ugly code.

ASProfilingSignpostStart(ASSignpostCATransactionLayout, 0, [CATransaction currentState]);
};
preCommitHandler = ^{
int state = [CATransaction currentState];
ASProfilingSignpostEnd(ASSignpostCATransactionLayout, 0, state, ASSignpostColorDefault);
ASProfilingSignpostStart(ASSignpostCATransactionCommit, 0, state);
};
postCommitHandler = ^{
ASProfilingSignpostEnd(ASSignpostCATransactionCommit, 0, [CATransaction currentState], ASSignpostColorDefault);
// Can't add new observers inside an observer. rdar://problem/31253952
dispatch_async(dispatch_get_main_queue(), ^{
[self registerTransactionObservers];
});
};
});

[CATransaction addCommitHandler:preLayoutHandler forPhase:kCATransactionPhasePreLayout];
[CATransaction addCommitHandler:preCommitHandler forPhase:kCATransactionPhasePreCommit];
[CATransaction addCommitHandler:postCommitHandler forPhase:kCATransactionPhasePostCommit];
}

#endif // AS_KDEBUG_ENABLE

- (instancetype)initWithRunLoop:(CFRunLoopRef)runloop retainObjects:(BOOL)retainsObjects handler:(void (^)(id _Nullable, BOOL))handlerBlock
{
if (self = [super init]) {
Expand Down Expand Up @@ -275,7 +329,7 @@ - (void)processQueue
return;
}

ASProfilingSignpostStart(0, self);
ASProfilingSignpostStart(ASSignpostRunLoopQueueBatch, self, 0);

// Snatch the next batch of items.
NSInteger maxCountToProcess = MIN(internalQueueCount, self.batchSize);
Expand Down Expand Up @@ -329,7 +383,7 @@ - (void)processQueue
CFRunLoopWakeUp(_runLoop);
}

ASProfilingSignpostEnd(0, self);
ASProfilingSignpostEnd(ASSignpostRunLoopQueueBatch, self, 0, ASSignpostColorDefault);
}

- (void)enqueue:(id)object
Expand Down
69 changes: 54 additions & 15 deletions Source/Base/ASLog.h
Original file line number Diff line number Diff line change
Expand Up @@ -16,18 +16,55 @@
//

#import <AsyncDisplayKit/ASAvailability.h>
#import <Foundation/Foundation.h>

#pragma once
/// The signposts we use. Signposts are grouped by color. The SystemTrace.tracetemplate file
/// should be kept up-to-date with these values.
typedef NS_ENUM(uint32_t, ASSignpostName) {
// Collection/Table (Blue)
ASSignpostDataControllerBatch = 300, // Alloc/layout nodes before collection update.
ASSignpostRangeControllerUpdate, // Ranges update pass.
ASSignpostCollectionUpdate, // Entire update process, from -endUpdates to [super perform…]

// Rendering (Green)
ASSignpostLayerDisplay = 325, // Client display callout.
ASSignpostRunLoopQueueBatch, // One batch of ASRunLoopQueue.

// Layout (Purple)
ASSignpostCalculateLayout = 350, // Start of calculateLayoutThatFits to end. Max 1 per thread.

// 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.
};

typedef NS_ENUM(uintptr_t, ASSignpostColor) {
ASSignpostColorBlue,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

By convention, perhaps set Blue = 0 to start off the enum (your choice)

ASSignpostColorGreen,
ASSignpostColorPurple,
ASSignpostColorOrange,
ASSignpostColorRed,
ASSignpostColorDefault
};

static inline ASSignpostColor ASSignpostGetColor(ASSignpostName name, ASSignpostColor colorPref) {
if (colorPref == ASSignpostColorDefault) {
return (ASSignpostColor)((name / 25) % 4);
} else {
return colorPref;
}
}

#define ASMultiplexImageNodeLogDebug(...)
#define ASMultiplexImageNodeCLogDebug(...)

#define ASMultiplexImageNodeLogError(...)
#define ASMultiplexImageNodeCLogError(...)

// Note: `<sys/kdebug_signpost.h>` only exists in Xcode 8 and later.
#if defined(PROFILE) && __has_include(<sys/kdebug_signpost.h>)
#define AS_KDEBUG_ENABLE defined(PROFILE) && __has_include(<sys/kdebug_signpost.h>)

#if AS_KDEBUG_ENABLE

#import <sys/kdebug_signpost.h>

Expand All @@ -45,21 +82,23 @@
#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));
// Currently we'll reserve arg3.
#define ASProfilingSignpost(name, identifier, arg2, color) \
AS_AT_LEAST_IOS10 ? kdebug_signpost(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color)) \
: syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_NONE, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color));

#define ASProfilingSignpostStart(name, identifier, arg2) \
AS_AT_LEAST_IOS10 ? kdebug_signpost_start(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, 0) \
: syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_START, (uintptr_t)identifier, (uintptr_t)arg2, 0, 0);

#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(name, identifier, arg2, color) \
AS_AT_LEAST_IOS10 ? kdebug_signpost_end(name, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color)) \
: syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, name) | DBG_FUNC_END, (uintptr_t)identifier, (uintptr_t)arg2, 0, ASSignpostGetColor(name, color));

#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)
#define ASProfilingSignpost(name, identifier, arg2, color)
#define ASProfilingSignpostStart(name, identifier, arg2)
#define ASProfilingSignpostEnd(name, identifier, arg2, color)

#endif
50 changes: 5 additions & 45 deletions Source/Details/ASDataController.mm
Original file line number Diff line number Diff line change
Expand Up @@ -40,8 +40,6 @@
//#define LOG(...) NSLog(__VA_ARGS__)
#define LOG(...)

#define AS_MEASURE_AVOIDED_DATACONTROLLER_WORK 0

#define RETURN_IF_NO_DATASOURCE(val) if (_dataSource == nil) { return val; }
#define ASSERT_ON_EDITING_QUEUE ASDisplayNodeAssertNotNil(dispatch_get_specific(&kASDataControllerEditingQueueKey), @"%@ must be called on the editing transaction queue.", NSStringFromSelector(_cmd))

Expand All @@ -54,13 +52,6 @@

typedef void (^ASDataControllerCompletionBlock)(NSArray<ASCollectionElement *> *elements, NSArray<ASCellNode *> *nodes);

#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
@interface ASDataController (AvoidedWorkMeasuring)
+ (void)_didLayoutNode;
+ (void)_expectToInsertNodes:(NSUInteger)count;
@end
#endif

@interface ASDataController () {
id<ASDataControllerLayoutDelegate> _layoutDelegate;

Expand Down Expand Up @@ -159,17 +150,14 @@ - (void)setLayoutDelegate:(id<ASDataControllerLayoutDelegate>)layoutDelegate
- (void)batchAllocateNodesFromElements:(NSArray<ASCollectionElement *> *)elements andLayout:(BOOL)shouldLayout batchSize:(NSInteger)batchSize batchCompletion:(ASDataControllerCompletionBlock)batchCompletionHandler
{
ASSERT_ON_EDITING_QUEUE;
#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
[ASDataController _expectToInsertNodes:elements.count];
#endif


if (elements.count == 0 || _dataSource == nil) {
batchCompletionHandler(@[], @[]);
return;
}

ASProfilingSignpostStart(2, _dataSource);
ASProfilingSignpostStart(ASSignpostDataControllerBatch, self, 0);

if (batchSize == 0) {
batchSize = [[ASDataController class] parallelProcessorCount] * kASDataControllerSizingCountPerProcessor;
}
Expand All @@ -182,8 +170,8 @@ - (void)batchAllocateNodesFromElements:(NSArray<ASCollectionElement *> *)element
NSArray<ASCellNode *> *nodes = [self _allocateNodesFromElements:batchedElements andLayout:shouldLayout];
batchCompletionHandler(batchedElements, nodes);
}
ASProfilingSignpostEnd(2, _dataSource);

ASProfilingSignpostEnd(ASSignpostDataControllerBatch, self, 0, (_dataSource != nil ? ASSignpostColorDefault : ASSignpostColorRed));
}

/**
Expand Down Expand Up @@ -228,10 +216,6 @@ - (void)_layoutNode:(ASCellNode *)node withConstrainedSize:(ASSizeRange)constrai
if (ASSizeRangeHasSignificantArea(sizeRange)) {
[self _layoutNode:node withConstrainedSize:sizeRange];
}

#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
[ASDataController _didLayoutNode];
#endif
}

allocatedNodeBuffer[i] = node;
Expand Down Expand Up @@ -836,27 +820,3 @@ - (void)_scheduleBlockOnMainSerialQueue:(dispatch_block_t)block
}

@end

#if AS_MEASURE_AVOIDED_DATACONTROLLER_WORK
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO this is a pretty valuable thing, to the point that we should have unit tests at least verifying that the skipping / cancellation of layout work never regresses; this was a very important development.

It does appear to add a good bit of complexity, although the code would be very similar with Signposts. With that in mind, and because a key area to extend the signpost system will be in ASDataController introspection, I'd vote to keep this around until it is refactored into something better.

That said, you and @nguyenhuy should make the call and proceed as you'd like - I know there are big plans across the stack and you're best equipped to decide how to get this kind of view into ASDC..

Copy link
Member Author

@Adlai-Holler Adlai-Holler Jun 18, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see that this mechanism is valuable to you, but I truly believe this isn't the way to implement this.

I spent some time this morning building a unit test to replace this. I failed, but ironically I discovered that the early bail is currently broken due to a subtle retain cycle where the node block retains the ASCollectionView. I've fixed that retain cycle, but I think it's worth noting that nobody noticed the feature was broken, possibly because this measurement feature is so obscure and unused. I care a lot about performance but I don't think this is the way to provide accountability.


static volatile int64_t _totalExpectedItems = 0;
static volatile int64_t _totalMeasuredNodes = 0;

@implementation ASDataController (WorkMeasuring)

+ (void)_didLayoutNode
{
int64_t measured = OSAtomicIncrement64(&_totalMeasuredNodes);
int64_t expected = _totalExpectedItems;
if (measured % 20 == 0 || measured == expected) {
NSLog(@"Data controller avoided work (underestimated): %lld / %lld", measured, expected);
}
}

+ (void)_expectToInsertNodes:(NSUInteger)count
{
OSAtomicAdd64((int64_t)count, &_totalExpectedItems);
}

@end
#endif
4 changes: 2 additions & 2 deletions Source/Details/ASRangeController.mm
Original file line number Diff line number Diff line change
Expand Up @@ -223,7 +223,7 @@ - (void)_updateVisibleNodeIndexPaths
[self _setVisibleNodes:newVisibleNodes];
return; // don't do anything for this update, but leave _rangeIsValid == NO to make sure we update it later
}
ASProfilingSignpostStart(1, self);
ASProfilingSignpostStart(ASSignpostRangeControllerUpdate, self, 0);

// Get the scroll direction. Default to using the previous one, if they're not scrolling.
ASScrollDirection scrollDirection = [_dataSource scrollDirectionForRangeController:self];
Expand Down Expand Up @@ -412,7 +412,7 @@ - (void)_updateVisibleNodeIndexPaths
NSLog(@"Range update complete; modifiedIndexPaths: %@", [self descriptionWithIndexPaths:modifiedIndexPaths]);
#endif

ASProfilingSignpostEnd(1, self);
ASProfilingSignpostEnd(ASSignpostRangeControllerUpdate, self, 0, ASSignpostColorDefault);
}

#pragma mark - Notification observers
Expand Down
2 changes: 0 additions & 2 deletions Source/Details/ASThread.h
Original file line number Diff line number Diff line change
Expand Up @@ -22,8 +22,6 @@
#import <stdbool.h>
#import <stdlib.h>

#import <libkern/OSAtomic.h>

#import <AsyncDisplayKit/ASAssert.h>
#import <AsyncDisplayKit/ASBaseDefines.h>

Expand Down
4 changes: 0 additions & 4 deletions Source/Details/Transactions/_ASAsyncTransaction.mm
Original file line number Diff line number Diff line change
Expand Up @@ -21,12 +21,10 @@
#import <AsyncDisplayKit/_ASAsyncTransaction.h>
#import <AsyncDisplayKit/_ASAsyncTransactionGroup.h>
#import <AsyncDisplayKit/ASAssert.h>
#import <AsyncDisplayKit/ASLog.h>
#import <AsyncDisplayKit/ASThread.h>
#import <list>
#import <map>
#import <mutex>
#import <stdatomic.h>

#define ASAsyncTransactionAssertMainThread() NSAssert(0 != pthread_main_np(), @"This method must be called on the main thread");

Expand Down Expand Up @@ -254,9 +252,7 @@ - (NSString *)description
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
Expand Down
14 changes: 14 additions & 0 deletions Source/Private/ASDisplayNode+AsyncDisplay.mm
Original file line number Diff line number Diff line change
Expand Up @@ -272,6 +272,20 @@ - (asyncdisplaykit_async_transaction_operation_block_t)_displayBlockWithAsynchro
};
}

/**
If we're profiling, wrap the display block with signpost start and end.
Color the interval red if cancelled, green otherwise.
*/
#if AS_KDEBUG_ENABLE
__unsafe_unretained id ptrSelf = self;
displayBlock = ^{
ASProfilingSignpostStart(ASSignpostLayerDisplay, ptrSelf, 0);
id result = displayBlock();
ASProfilingSignpostEnd(ASSignpostLayerDisplay, ptrSelf, 0, isCancelledBlock() ? ASSignpostColorRed : ASSignpostColorGreen);
return result;
};
#endif

return displayBlock;
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,6 @@
//

#import "ASTextDebugOption.h"
#import <libkern/OSAtomic.h>
#import <pthread.h>

static pthread_mutex_t _sharedDebugLock;
Expand Down
Loading