Permalink
Browse files

Add "labeled start times" to logger, plus a few other changes.

Summary:
Address @mmarucheck's comments from D481502.

- Add notion of labeled start times to the logger.
- Removed log state from the places where we were doing perf logging.
- Improved session state transition spew.
- Factored @clang's debugger output for use with transition spew.

Test Plan: Tested against apps for seeing perf characteristics.

Reviewers: mmarucheck, jacl, clang

Reviewed By: mmarucheck

CC: msdkexp@, yariv

Differential Revision: https://phabricator.fb.com/D483630
  • Loading branch information...
1 parent c54e91d commit f81b28ef2cf64a768be7172e2e26f91f5ef0c2c2 @gregschechter gregschechter committed Jun 1, 2012
@@ -42,7 +42,7 @@ - (BOOL)application:(UIApplication *)application didFinishLaunchingWithOptions:(
// wireup successfully.
// http://stackoverflow.com/questions/1725881/unknown-class-myclass-in-interface-builder-file-error-at-runtime
[FBFriendPickerViewController class];
-
+
self.session = [[FBSession alloc] init];
self.window = [[UIWindow alloc] initWithFrame:[[UIScreen mainScreen] bounds]];
@@ -42,7 +42,6 @@ - (void)initialize;
@implementation FBFriendPickerViewController {
BOOL _allowsMultipleSelection;
- unsigned long _loadStartTime;
}
@synthesize dataSource = _dataSource;
@@ -183,7 +182,8 @@ - (FBSession*)session {
- (void)viewDidLoad
{
[super viewDidLoad];
- _loadStartTime = [FBUtility currentTimeInMilliseconds];
+ [FBLogger registerCurrentTime:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ withTag:self];
CGRect bounds = self.view.bounds;
if (!self.tableView) {
@@ -293,12 +293,10 @@ - (void)pagingLoader:(FBGraphObjectPagingLoader*)pagingLoader didLoadData:(NSDic
// This logging currently goes here because we're effectively complete with our initial view when
// the first page of results come back. In the future, when we do caching, we will need to move
// this to a more appropriate place (e.g., after the cache has been brought in).
- if (_loadStartTime != 0) {
- [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
- formatString:@"Friend Picker: first render %d msec",
- [FBUtility currentTimeInMilliseconds] - _loadStartTime];
- _loadStartTime = 0;
- }
+ [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ timestampTag:self
+ formatString:@"Friend Picker: first render "]; // logger will append "%d msec"
+
if ([self.delegate respondsToSelector:@selector(friendPickerViewControllerDataDidChange:)]) {
[self.delegate friendPickerViewControllerDataDidChange:self];
View
@@ -70,6 +70,15 @@
+ (void)singleShotLogEntry:(NSString *)loggingBehavior
formatString:(NSString *)formatString, ...;
++ (void)singleShotLogEntry:(NSString *)loggingBehavior
+ timestampTag:(NSObject *)timestampTag
+ formatString:(NSString *)formatString, ...;
+
+// Register a timestamp label with the "current" time, to then be retrieved by singleShotLogEntry
+// to include a duration.
++ (void)registerCurrentTime:(NSString *)loggingBehavior
+ withTag:(NSObject *)timestampTag;
+
// When logging strings, replace all instances of 'replace' with instances of 'replaceWith'.
+ (void)registerStringToReplace:(NSString *)replace
replaceWith:(NSString *)replaceWith;
View
@@ -20,11 +20,11 @@
static NSUInteger g_serialNumberCounter = 1111;
static NSMutableDictionary *g_stringsToReplace = nil;
+static NSMutableDictionary *g_startTimesWithTags = nil;
@interface FBLogger ()
@property (nonatomic, retain, readonly) NSMutableString *internalContents;
-@property (nonatomic, retain, readonly) NSMutableDictionary *stringsToReplace;
@end
@@ -34,7 +34,6 @@ @implementation FBLogger
@synthesize isActive = _isActive;
@synthesize loggingBehavior = _loggingBehavior;
@synthesize loggerSerialNumber = _loggerSerialNumber;
-@synthesize stringsToReplace = _stringsToReplace;
// Lifetime
@@ -127,18 +126,71 @@ + (void)singleShotLogEntry:(NSString *)loggingBehavior
}
+ (void)singleShotLogEntry:(NSString *)loggingBehavior
- formatString:(NSString *)formatString, ...; {
+ formatString:(NSString *)formatString, ... {
if ([[FBSession loggingBehavior] containsObject:loggingBehavior]) {
va_list vaArguments;
va_start(vaArguments, formatString);
- NSString *logString = [[NSString alloc] initWithFormat:formatString arguments:vaArguments];
+ NSString *logString = [[[NSString alloc] initWithFormat:formatString arguments:vaArguments] autorelease];
va_end(vaArguments);
[self singleShotLogEntry:loggingBehavior logEntry:logString];
}
}
+
++ (void)singleShotLogEntry:(NSString *)loggingBehavior
+ timestampTag:(NSObject *)timestampTag
+ formatString:(NSString *)formatString, ... {
+
+ if ([[FBSession loggingBehavior] containsObject:loggingBehavior]) {
+ va_list vaArguments;
+ va_start(vaArguments, formatString);
+ NSString *logString = [[[NSString alloc] initWithFormat:formatString arguments:vaArguments] autorelease];
+ va_end(vaArguments);
+
+ // Start time of this "timestampTag" is stashed in the dictionary.
+ // Treat the incoming object tag simply as an address, since it's only used to identify during lifetime. If
+ // we send in as an object, the dictionary will try to copy it.
+ NSNumber *tagAsNumber = [NSNumber numberWithUnsignedLong:(unsigned long)(void *)timestampTag];
+ NSNumber *startTimeNumber = [g_startTimesWithTags objectForKey:tagAsNumber];
+
+ // Only log if there's been an associated start time.
+ if (startTimeNumber) {
+ unsigned long elapsed = [FBUtility currentTimeInMilliseconds] - startTimeNumber.unsignedLongValue;
+ [g_startTimesWithTags removeObjectForKey:tagAsNumber]; // served its purpose, remove
+
+ // Log string is appended with "%d msec", with nothing intervening. This gives the most control to the caller.
+ logString = [NSString stringWithFormat:@"%@%d msec", logString, elapsed];
+
+ [self singleShotLogEntry:loggingBehavior logEntry:logString];
+ }
+ }
+}
+
++ (void)registerCurrentTime:(NSString *)loggingBehavior
+ withTag:(NSObject *)timestampTag {
+
+ if ([[FBSession loggingBehavior] containsObject:loggingBehavior]) {
+
+ if (!g_startTimesWithTags) {
+ g_startTimesWithTags = [[NSMutableDictionary alloc] init];
+ }
+
+ NSAssert(g_startTimesWithTags.count < 1000,
+ @"Unexpectedly large number of outstanding perf logging start times, something is likely wrong.");
+
+ unsigned long currTime = [FBUtility currentTimeInMilliseconds];
+
+ // Treat the incoming object tag simply as an address, since it's only used to identify during lifetime. If
+ // we send in as an object, the dictionary will try to copy it.
+ unsigned long tagAsNumber = (unsigned long)(void *)timestampTag;
+ [g_startTimesWithTags setObject:[NSNumber numberWithUnsignedLong:currTime]
+ forKey:[NSNumber numberWithUnsignedLong:tagAsNumber]];
+ }
+}
+
+
+ (void)registerStringToReplace:(NSString *)replace
replaceWith:(NSString *)replaceWith {
@@ -22,8 +22,6 @@
#import "FBPlacePickerViewController.h"
#import "FBRequest.h"
#import "FBRequestConnection.h"
-#import "FBUtility.h"
-
static const NSInteger searchTextChangedTimerInterval = 2;
static const NSInteger defaultResultsLimit = 100;
@@ -50,7 +48,6 @@ - (void)updateView;
@implementation FBPlacePickerViewController {
BOOL _hasSearchTextChangedSinceLastQuery;
- unsigned long _loadStartTime;
}
@synthesize dataSource = _dataSource;
@@ -201,7 +198,8 @@ - (void)loadData
- (void)viewDidLoad
{
[super viewDidLoad];
- _loadStartTime = [FBUtility currentTimeInMilliseconds];
+ [FBLogger registerCurrentTime:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ withTag:self];
CGRect bounds = self.view.bounds;
if (!self.tableView) {
@@ -354,12 +352,9 @@ - (void)pagingLoader:(FBGraphObjectPagingLoader*)pagingLoader didLoadData:(NSDic
// This logging currently goes here because we're effectively complete with our initial view when
// the first page of results come back. In the future, when we do caching, we will need to move
// this to a more appropriate place (e.g., after the cache has been brought in).
- if (_loadStartTime != 0) {
- [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
- formatString:@"Places Picker: first render %d msec",
- [FBUtility currentTimeInMilliseconds] - _loadStartTime];
- _loadStartTime = 0;
- }
+ [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ timestampTag:self
+ formatString:@"Places Picker: first render "]; // logger will append "%d msec"
if ([self.delegate respondsToSelector:@selector(placePickerViewControllerDataDidChange:)]) {
[self.delegate placePickerViewControllerDataDidChange:self];
View
@@ -94,7 +94,6 @@ @interface FBSession () <FBLoginDialogDelegate> {
@property(readonly) NSString *appBaseUrl;
@property(readwrite, retain) FBLoginDialog *loginDialog;
@property(readwrite, retain) NSThread *affinitizedThread;
-@property(readwrite) unsigned long previousTransitionBeginTime;
// private members
- (void)notifyOfState:(FBSessionState)state;
@@ -106,6 +105,7 @@ - (void)authorizeWithFBAppAuth:(BOOL)tryFBAppAuth
+ (NSString*)appIDFromPLIST;
+ (BOOL)areRequiredPermissions:(NSArray*)requiredPermissions
aSubsetOfPermissions:(NSArray*)cachedPermissions;
++ (NSString *)sessionStateDescription:(FBSessionState)sessionState;
@end
@@ -128,8 +128,7 @@ @implementation FBSession : NSObject
attemptedRefreshDate = _attemptedRefreshDate,
loginDialog = _loginDialog,
affinitizedThread = _affinitizedThread,
- loginHandler = _loginHandler,
- previousTransitionBeginTime = _previousTransitionBeginTime;
+ loginHandler = _loginHandler;
#pragma mark Lifecycle
@@ -188,8 +187,8 @@ - (id)initWithAppID:(NSString*)appID
self.refreshDate = nil;
self.state = FBSessionStateCreated;
self.affinitizedThread = [NSThread currentThread];
- self.previousTransitionBeginTime = [FBUtility currentTimeInMilliseconds];
-
+ [FBLogger registerCurrentTime:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ withTag:self];
//first notification
[self notifyOfState:self.state];
@@ -477,7 +476,9 @@ - (BOOL)transitionToState:(FBSessionState)state
// invalid transition short circuits
if (!isValidTransition) {
[FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_SESSION_STATE_TRANSITIONS
- logEntry:[NSString stringWithFormat:@"FBSession !transitionToState:%i fromState:%i", state, statePrior]];
+ logEntry:[NSString stringWithFormat:@"FBSession **INVALID** transition from %@ to %@",
+ [FBSession sessionStateDescription:statePrior],
+ [FBSession sessionStateDescription:state]]];
return false;
}
@@ -493,14 +494,18 @@ - (BOOL)transitionToState:(FBSessionState)state
}
// valid transitions notify
- unsigned long currTime = [FBUtility currentTimeInMilliseconds];
- NSString *logString = [NSString stringWithFormat:@"FBSession transition toState:%i fromState:%i - %d msec",
- state,
- statePrior,
- currTime - self.previousTransitionBeginTime];
- self.previousTransitionBeginTime = currTime;
+ NSString *logString = [NSString stringWithFormat:@"FBSession transition from %@ to %@ ",
+ [FBSession sessionStateDescription:statePrior],
+ [FBSession sessionStateDescription:state]];
[FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_SESSION_STATE_TRANSITIONS logEntry:logString];
- [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS logEntry:logString];
+
+ [FBLogger singleShotLogEntry:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ timestampTag:self
+ formatString:@"%@", logString];
+
+ // Re-start session transition timer for the next time around.
+ [FBLogger registerCurrentTime:FB_LOG_BEHAVIOR_PERFORMANCE_CHARACTERISTICS
+ withTag:self];
// identify whether we will update token and date, and what the values will be
BOOL changingTokenAndDate = false;
@@ -875,9 +880,9 @@ + (NSDate*)expirationDateFromExpirationTimeString:(NSString*)expirationTime {
#pragma mark -
#pragma mark Debugging helpers
-- (NSString*)description {
++ (NSString *)sessionStateDescription:(FBSessionState)sessionState {
NSString *stateDescription = nil;
- switch (self.state) {
+ switch (sessionState) {
case FBSessionStateCreated:
stateDescription = @"FBSessionStateCreated";
break;
@@ -900,6 +905,13 @@ - (NSString*)description {
stateDescription = @"[Unknown]";
break;
}
+
+ return stateDescription;
+}
+
+
+- (NSString*)description {
+ NSString *stateDescription = [FBSession sessionStateDescription:self.state];
return [NSString stringWithFormat:@"<%@: %p, state: %@, loginHandler: %p, appID: %@, urlSchemeSuffix: %@, tokenCachingStrategy:%@, expirationDate: %@, refreshDate: %@, attemptedRefreshDate: %@, permissions:%@>",
NSStringFromClass([self class]),
self,

0 comments on commit f81b28e

Please sign in to comment.