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?
