I've been working on a game with an engine that updates 20 times per seconds. I've got to point now where I want to start getting some performance figures and tweak the rendering and logic updates. In order to do so I started to add some timing code to my game loop, implemented as follows...
NSDate* startTime = [NSDate date];
// Game update logic here....
// Also timing of smaller internal events
NSDate* endTime = [NSDate date];
[endTime timeIntervalSinceDate:startTime];
I noticed however that when I timed blocks within the outer timing logic that the time they took to execute did not sum up to match the overall time taken.
So I wrote a small unit test to demonstrate the problem in which I time the overall time taken to complete the test and then 10 smaller events, here it is...
- (void)testThatSumOfTimingsMatchesOverallTiming {
NSDate* startOfOverallTime = [NSDate date];
// Variable to hold summation of smaller timing events in the upcoming loop...
float sumOfIndividualTimes = 0.0;
NSTimeInterval times[10] = {0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0};
for (int i = 0; i < 10; i++) {
NSDate* startOfIndividualTime = [NSDate date];
// Kill some time...
sleep(1);
NSDate* endOfIndividualTime = [NSDate date];
times[i] = [endOfIndividualTime timeIntervalSinceDate:startOfIndividualTime];
sumOfIndividualTimes += times[i];
}
NSDate* endOfOverallTime = [NSDate date];
NSTimeInterval overallTimeTaken = [endOfOverallTime timeIntervalSinceDate:startOfOverallTime];
NSLog(@"Sum of individual times: %fms", sumOfIndividualTimes);
NSLog(@"Overall time: %fms", overallTimeTaken);
STAssertFalse(TRUE, @"");
}
And here's the output...
Sum of individual times: 10.001377ms
Overall time: 10.016834ms
Which illustrates my problem quite clearly. The overall time was 0.000012ms but the smaller events took only 0.000001ms. So what happened to the other 0.000011ms?
Is there anything that looks particularly wrong with my code? Or is there an alternative timing mechanism I should use?
Well, there is some time required to run [NSDate date] and [endTime timeIntervalSinceDate:startDate] which probably accounts for the difference.
However, I would use CACurrentMediaTime() which returns a CFTimeInterval (which is just a double), or mach_absolute_time() which returns an unsigned long int. Both of these avoid object creation and probably take less time.
Of course, you'll still be subtracting two numbers every frame, which takes time. My suggestion to get around that would be to just use lastFrameEnd:
CFTimeInterval lastFrameEnd = CACurrentMediaTime();
while (true) {
// Game update logic here....
// Also timing of smaller internal events
CFTimeInterval frameEnd = CACurrentMediaTime();
CFTimeInterval duration = frameEnd - lastFrameEnd; //Use this
lastFrameEnd = frameEnd;
}
This takes into account the time taken for the end of one frame to the end of the next, including the time taken for the subtraction and method calls.