CodeTimestamps.m

//
//  CodeTimestamps.m
//
//  Created by Tyler Neylon on 12/29/10.
//
//
//  Reference for the timestamp functions:
//    http://developer.apple.com/library/mac/#qa/qa2004/qa1398.html
//

// This code would be cleaner if it used NSObject+Be for memory
// management, but I've decided to use standard methods instead,
// to make it easier to use CodeTimestamps.{h,m} on their own.

// I'm also aware that the Build & Analyze tool produces some warnings
// for this code, but I've examined them and I don't think they're legit problems.
// I would like to tweak things to get rid of the warnings with zero performance
// cost, but that's a low priority for me, so I may not do it anytime soon.

#import "CodeTimestamps.h"

#import <mach/mach.h>
#import <mach/mach_time.h>

#define kNumSlowestChunks 5
#define kNumMidPoints 5

static NSMutableArray *chunkData = nil;

@class ChunkTimeInterval;

@interface LogHelper : NSObject {
@private
  NSTimer *logTimer;
  NSMutableArray *pendingLines;
  NSMutableArray *slowestChunks;
}

+ (LogHelper *)sharedInstance;

- (void)startLoggingTimer;
- (void)printOutTimingData:(NSTimer *)timer;
- (void)addLogString:(NSString *)newString;

- (void)maybeAddTimeIntervalAsSlowest:(ChunkTimeInterval *)timeInterval;
- (void)logSlowestChunks;

- (void)consolidateTimeIntervals:(NSMutableArray *)timeIntervals;

@end

@interface ChunkStamp : NSObject {
 @public
  const char *fnName;
  int lineNum;
  uint64_t timestamp;
  NSThread *thread;
  BOOL isStart;
  BOOL isEnd;
}

- (NSComparisonResult)compare:(id)other;

@end

void printAllLogs() {
	[[LogHelper sharedInstance] printOutTimingData:nil];
}

uint64_t NanosecondsFromTimeInterval(uint64_t timeInterval) {
  static struct mach_timebase_info timebase_info;
  OneTimeCall(mach_timebase_info(&timebase_info));
  timeInterval *= timebase_info.numer;
  timeInterval /= timebase_info.denom;
  return timeInterval;
}

// This function needs to be _fast_ to minimize interfering with
// timing data.  So we don't actually NSLog during it, using LogHelper.
void LogTimeStampInMethod(const char *fnName, int lineNum) {
  OneTimeCall([[LogHelper sharedInstance] startLoggingTimer]);
  static uint64_t lastTimestamp = 0;
  uint64_t thisTimestamp = mach_absolute_time();
  NSString *logStr = nil;
  if (lastTimestamp == 0) {
    logStr = [NSString stringWithFormat:@"* %s:%4d", fnName, lineNum];
  } else {
    uint64_t elapsed = NanosecondsFromTimeInterval(thisTimestamp - lastTimestamp);
    logStr = [NSString stringWithFormat:@"* %s:%4d - %9llu nsec since last timestamp",
              fnName, lineNum, elapsed];
  }
  [[LogHelper sharedInstance] addLogString:logStr];
  lastTimestamp = thisTimestamp;
}

void InitChunkData() {
  if (chunkData) return;
  chunkData = [NSMutableArray new];
}

void LogTimestampChunkInMethod(const char *fnName, int lineNum, BOOL isStart, BOOL isEnd) {
  OneTimeCall(InitChunkData());
  OneTimeCall([[LogHelper sharedInstance] startLoggingTimer]);
  ChunkStamp *stamp = [[ChunkStamp new] autorelease];
  stamp->fnName = fnName;
  stamp->lineNum = lineNum;
  stamp->timestamp = mach_absolute_time();
  stamp->thread = [NSThread currentThread];
  stamp->isStart = isStart;
  stamp->isEnd = isEnd;
  @synchronized(chunkData) {
    [chunkData addObject:stamp];
  }
}

@interface ChunkTimeInterval : NSObject {
@public
  NSString *intervalName;  // strong
  uint64_t nanoSecsElapsed;
}
- (id)initFromStamp:(ChunkStamp *)stamp1 toStamp:(ChunkStamp *)stamp2;
@end

@implementation ChunkTimeInterval
- (id)initFromStamp:(ChunkStamp *)stamp1 toStamp:(ChunkStamp *)stamp2 {
  if (![super init]) return nil;
  intervalName = [[NSString stringWithFormat:@"%s:%d - %s:%d",
                   stamp1->fnName, stamp1->lineNum, stamp2->fnName, stamp2->lineNum] retain];
  nanoSecsElapsed = NanosecondsFromTimeInterval(stamp2->timestamp - stamp1->timestamp);
  return self;
}
- (void)dealloc {
  [intervalName release];
  [super dealloc];
}
- (NSString *)description {
  return [NSString stringWithFormat:@"<%@ %p> %@ %llu", [self class], self, intervalName, nanoSecsElapsed];
}
@end



@implementation LogHelper

+ (LogHelper *)sharedInstance {
  static LogHelper *instance = nil;
  if (instance == nil) instance = [LogHelper new];
  return instance;
}

- (id)init {
  if (![super init]) return nil;
  pendingLines = [NSMutableArray new];
  slowestChunks = [NSMutableArray new];
  return self;
}

- (void)startLoggingTimer {
  if (logTimer) return;
  logTimer = [NSTimer scheduledTimerWithTimeInterval:kLogTimeInterval
                                              target:self
                                            selector:@selector(printOutTimingData:)
                                            userInfo:nil
                                             repeats:YES];
}
- (void)printOutTimingData:(NSTimer *)timer {
  BOOL didLogAnything = NO;
  
  // Handle pending lines.
  if ([pendingLines count]) {
    NSLog(@"==== Start non-chunk timestamp data (from \"LogTimestamp\") ====");
    for (NSString *logString in pendingLines) {
      NSLog(@"%@", logString);
    }
    [pendingLines removeAllObjects];
    didLogAnything = YES;
  }
    
  // Handle chunk data.
  if ([chunkData count]) {
    NSLog(@"==== Start chunk timestamp data (from \"LogTimestamp{Start,Mid,End}Chunk\") ====");
    @synchronized(chunkData) {
      [chunkData sortUsingSelector:@selector(compare:)];
      NSThread *thread = nil;
      NSMutableArray *timeIntervals = [NSMutableArray array];
      uint64_t totalNanoSecsThisChunk;
      uint64_t totalNanoSecsThisThread;
      int numRunsThisThread;
      BOOL thisThreadHadChunks = NO;
      BOOL midChunk = NO;
      ChunkStamp *lastStamp = nil;
      NSString *chunkName = nil;
      for (ChunkStamp *chunkStamp in chunkData) {
        if (chunkStamp->thread != thread) {
          if (thisThreadHadChunks) {
            NSLog(@"++ Chunk = %@, avg time = %.4fs", chunkName,
                  (float)totalNanoSecsThisThread / numRunsThisThread / 1e9);
          }
          
          thread = chunkStamp->thread;
          NSLog(@"--- Data for thread %p ---", thread);
          [timeIntervals removeAllObjects];
          midChunk = NO;
          thisThreadHadChunks = NO;
          totalNanoSecsThisChunk = 0;
          totalNanoSecsThisThread = 0;
          numRunsThisThread = 0;
        }
        if (chunkStamp->isStart) {
          if (midChunk) {
            NSLog(@"ERROR: LogTimestampStartChunk hit twice without a LogTimestampEndChunk between them.");
          }
          midChunk = YES;
          thisThreadHadChunks = YES;
          chunkName = [NSString stringWithFormat:@"%s:%d", chunkStamp->fnName, chunkStamp->lineNum];
        } else if (midChunk) {
          ChunkTimeInterval *timeInterval = [[[ChunkTimeInterval alloc] initFromStamp:lastStamp toStamp:chunkStamp] autorelease];
          [timeIntervals addObject:timeInterval];
          totalNanoSecsThisChunk += timeInterval->nanoSecsElapsed;
          if (chunkStamp->isEnd) {
            totalNanoSecsThisThread += totalNanoSecsThisChunk;
            numRunsThisThread++;
            chunkName = [NSString stringWithFormat:@"%@ - %s:%d", chunkName, chunkStamp->fnName, chunkStamp->lineNum];
            NSLog(@"+ Chunk = %@, time = %.4fs", chunkName, (float)totalNanoSecsThisChunk/1e9);
            
            [self consolidateTimeIntervals:timeIntervals];
            for (int i = 0; i < [timeIntervals count] && i < kNumMidPoints; ++i) {
              ChunkTimeInterval *timeInterval = [timeIntervals objectAtIndex:i];
              int percentTime = (int)round(100.0 * (float)timeInterval->nanoSecsElapsed / totalNanoSecsThisChunk);
              NSLog(@"    %2d%% in %@", percentTime, timeInterval->intervalName);
            }
            
            ChunkTimeInterval *totalInterval = [[ChunkTimeInterval new] autorelease];
            totalInterval->intervalName = [chunkName retain];
            totalInterval->nanoSecsElapsed = totalNanoSecsThisChunk;
            [self maybeAddTimeIntervalAsSlowest:totalInterval];
            
            [timeIntervals removeAllObjects];
            totalNanoSecsThisChunk = 0;
            midChunk = NO;
          }
        }
        lastStamp = chunkStamp;
      }
      if (thisThreadHadChunks) {
        NSLog(@"++ Chunk = %@, avg time = %d nsec", chunkName,
              totalNanoSecsThisThread / numRunsThisThread);
      }
      [chunkData removeAllObjects];
    }
    didLogAnything = YES;
  }
  if (didLogAnything) {
    [self logSlowestChunks];
    NSLog(@"==== End timestamp data ====");
  }
}

- (void)addLogString:(NSString *)newString {
  [pendingLines addObject:newString];
}

- (void)maybeAddTimeIntervalAsSlowest:(ChunkTimeInterval *)timeInterval {
  if ([slowestChunks count] < kNumSlowestChunks ||
      ((ChunkTimeInterval *)[slowestChunks lastObject])->nanoSecsElapsed < timeInterval->nanoSecsElapsed) {
    [slowestChunks addObject:timeInterval];
    NSSortDescriptor *sortByTime = [[[NSSortDescriptor alloc] initWithKey:@"nanoSecsElapsed" ascending:NO] autorelease];
    [slowestChunks sortUsingDescriptors:[NSArray arrayWithObject:sortByTime]];
    if ([slowestChunks count] > kNumSlowestChunks) [slowestChunks removeLastObject];
  }
}

- (void)logSlowestChunks {
  if ([slowestChunks count] == 0) return;
  NSLog(@"==== Slowest chunks so far ====");
  for (ChunkTimeInterval *timeInterval in slowestChunks) {
    NSLog(@"# Chunk = %@, time = %.4fs", timeInterval->intervalName, (float)timeInterval->nanoSecsElapsed/1e9);
  }
}

- (void)consolidateTimeIntervals:(NSMutableArray *)timeIntervals {
  NSSortDescriptor *sortByName = [[[NSSortDescriptor alloc] initWithKey:@"intervalName" ascending:YES] autorelease];
  [timeIntervals sortUsingDescriptors:[NSArray arrayWithObject:sortByName]];
  
  NSMutableArray *consolidatedIntervals = [NSMutableArray array];
  NSString *lastName = nil;
  ChunkTimeInterval *thisInterval = nil;
  for (ChunkTimeInterval *timeInterval in timeIntervals) {
    if ([lastName isEqualToString:timeInterval->intervalName]) {
      thisInterval->nanoSecsElapsed += timeInterval->nanoSecsElapsed;
    } else {
      thisInterval = [[ChunkTimeInterval new] autorelease];
      thisInterval->intervalName = [timeInterval->intervalName retain];
      thisInterval->nanoSecsElapsed = timeInterval->nanoSecsElapsed;
      [consolidatedIntervals addObject:thisInterval];
    }
    lastName = timeInterval->intervalName;
  }
  [timeIntervals removeAllObjects];
  [timeIntervals addObjectsFromArray:consolidatedIntervals];
  
  NSSortDescriptor *sortByTime = [[[NSSortDescriptor alloc] initWithKey:@"nanoSecsElapsed" ascending:NO] autorelease];
  [timeIntervals sortUsingDescriptors:[NSArray arrayWithObject:sortByTime]];
}

@end

@implementation ChunkStamp

- (NSComparisonResult)compare:(id)other {
  ChunkStamp *otherStamp = (ChunkStamp *)other;
  if (thread != otherStamp->thread) {
    return (thread < otherStamp->thread ? NSOrderedAscending : NSOrderedDescending);
  }
  if (strcmp(fnName, otherStamp->fnName) != 0) {
    return (strcmp(fnName, otherStamp->fnName) < 0 ? NSOrderedAscending : NSOrderedDescending);
  }
  if (timestamp == otherStamp->timestamp) return NSOrderedSame;
  return (timestamp < otherStamp->timestamp ? NSOrderedAscending : NSOrderedDescending);
}

@end