openFrameworks timing issues using ofGetLastFrameTime

Hi!

I’m writing a small crossplatform game using OF but ran into some issues with the timing.

1. Intro
Currently I am trying to achieve smooth camera/player movement. To change an object in the gameworld or move the camera itself, I am using a “delta time” which is the time difference between the current and previous frame.

So if I want to move a block, I multiply the x position value with a movement factor and the delta time.

Example:
Position.x += movementFactor * deltaTime;

This post: http://forum.openframeworks.cc/t/for-those-who-don’t-know-about-framerate…a-little-demo/6443/2
shows that I can get the deltaTime from the method ofGetLastFrameTime()

2. Problem
When I’m using the technique above, and I’m moving the camera at a fixed speed (movementFactor is set to 0.5). The movement is not as smooth as I hoped. It is actually showing some lag/stutter for reasons I dont know. On Windows you can see random framerate spikes but on Android its even more obvious.

3. Analysis
Since I didn’t knew what was causing it (I’m only drawing a few squares, not a full featured 3d object), I made a really bare demo application to test out what was going on (The code can be downloaded from the link below).

The demo shows different methods to “generate” the deltaTime value.

  • First method is using ofGetLastFrameTime() which is the implementation by openFrameworks
  • Second method is a high resolution timer I downloaded from http://gafferongames.com/game-physics/fix-your-timestep/ (also includes linux/apple implementations)
  • Third method is using ofGetElapsedTimeMillis() and compares the result with the value from the previous frame (less precise, not used, but included just for reference purposes)

I’ve set the demo to run at a target framerate of 30 fps and recorded the results using a deltaTime implemented with the first method as with the second method (for both Windows and Android).

The resulting video can be found here:
http://www.youtube.com/watch?v=yTa6xrsso2g

  1. Running on windows and using ofGetLastFrameTime()
  2. Running on windows and using high res timer
  3. Running on android and using ofGetLastFrameTime()
  4. Running on android and using high res timer
  • The video shows that using ofGetLastFrameTime() shows some jerky framerate on windows but horrible on android.
  • While not ideal, the high res timer is much smoother.

4. Debug output
When I compared the deltaTime methods on windows I saw that the ofGetLastFrameTime() did not always matched up with the timing from the other 2 methods:

Note:

LastFrameTime = deltaTime by using ofGetLastFrameTime()
LastUpdateTime = deltaTime by using the high res timer
TotalGameTime = Total application run time ofGetElapsedTimeMillis();
ElapsedGameTime = deltaTime by using ofGetElapsedTimeMillis() (subtract the current from previous frame)

Windows snippet:

  
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0329933 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 6951 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 33 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0328031 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 6984 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 33 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0373755 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 7021 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 37 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0285368 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 7050 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 29 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0330977 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 7083 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 33 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0329924 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 7116 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 33 ms   
OF: OF_LOG_NOTICE: ------------------------------------------  

While the LastFrameTime ofGetLastFrameTime() always stated 0.033, the other two methods (both matched with each other although at different precision) clearly showed a different value.

on Android I get very different results:

  
11-12 21:30:22.603: I/OF(25841): ------------------------------------------  
11-12 21:30:22.633: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.019 sec   
11-12 21:30:22.633: I/OF(25841): LastUpdateTime (High precision): 0.038353 sec   
11-12 21:30:22.633: I/OF(25841): TotalGameTime  (OpenFrameworks): 9935 ms   
11-12 21:30:22.643: I/OF(25841): ElapsedGameTime (OF  deltaTime): 38 ms   
11-12 21:30:22.643: I/OF(25841): ------------------------------------------   
11-12 21:30:22.673: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.012 sec   
11-12 21:30:22.673: I/OF(25841): LastUpdateTime (High precision): 0.0365858 sec   
11-12 21:30:22.673: I/OF(25841): TotalGameTime  (OpenFrameworks): 9972 ms   
11-12 21:30:22.673: I/OF(25841): ElapsedGameTime (OF  deltaTime): 37 ms   
11-12 21:30:22.673: I/OF(25841): ------------------------------------------   
11-12 21:30:22.713: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.015 sec   
11-12 21:30:22.713: I/OF(25841): LastUpdateTime (High precision): 0.0350304 sec   
11-12 21:30:22.713: I/OF(25841): TotalGameTime  (OpenFrameworks): 10007 ms   
11-12 21:30:22.713: I/OF(25841): ElapsedGameTime (OF  deltaTime): 35 ms   
11-12 21:30:22.713: I/OF(25841): ------------------------------------------   
11-12 21:30:22.753: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.016 sec   
11-12 21:30:22.753: I/OF(25841): LastUpdateTime (High precision): 0.0407324 sec   
11-12 21:30:22.753: I/OF(25841): TotalGameTime  (OpenFrameworks): 10048 ms   
11-12 21:30:22.753: I/OF(25841): ElapsedGameTime (OF  deltaTime): 41 ms   
11-12 21:30:22.753: I/OF(25841): ------------------------------------------   
11-12 21:30:22.783: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.011 sec   
11-12 21:30:22.783: I/OF(25841): LastUpdateTime (High precision): 0.0376215 sec   
11-12 21:30:22.783: I/OF(25841): TotalGameTime  (OpenFrameworks): 10085 ms   
11-12 21:30:22.783: I/OF(25841): ElapsedGameTime (OF  deltaTime): 37 ms   
11-12 21:30:22.783: I/OF(25841): ------------------------------------------   
11-12 21:30:22.823: I/OF(25841): LastFrameTime  (OpenFrameworks): 0.016 sec   
11-12 21:30:22.823: I/OF(25841): LastUpdateTime (High precision): 0.0357313 sec   
11-12 21:30:22.823: I/OF(25841): TotalGameTime  (OpenFrameworks): 10121 ms   
11-12 21:30:22.823: I/OF(25841): ElapsedGameTime (OF  deltaTime): 36 ms   
11-12 21:30:22.823: I/OF(25841): ------------------------------------------   

5. Help?
I really would like to use openFrameworks for my game project (shared code bases are a relief), but these timing issues are rather critical for my application. Any suggestions on how to solve this problem?

Demo sourcode (requires openframeworks from github, develop branch):
http://falcon4ever.pcsx2.net/timingExample.zip

yes there was something wrong in the way the time for one frame was calculated in android. I’ve uploaded a fix to github can you test if it fixes it for you.

Thanks arturo!

I tested the fix and it looks the android build is a bit better although there are still some weird things going on with the timings.

Full LogCat: http://falcon4ever.pcsx2.net/TimingAndroidLogCat.txt

For example:

  
11-13 13:35:57.343: I/OF(754): ------------------------------------------   
11-13 13:35:57.383: I/OF(754): LastFrameTime  (OpenFrameworks): 0.024 sec   
11-13 13:35:57.383: I/OF(754): LastUpdateTime (High precision): 0.039237 sec   
11-13 13:35:57.383: I/OF(754): TotalGameTime  (OpenFrameworks): 2358 ms   
11-13 13:35:57.383: I/OF(754): ElapsedGameTime (OF  deltaTime): 39 ms   
11-13 13:35:57.383: I/OF(754): ------------------------------------------  
  

  • ofGetLastFrameTime() reports a frametime of 24 ms
  • When I measure it, its around 39 ms

the opposite happens as well:

  
  
11-13 13:35:57.413: I/OF(754): LastFrameTime  (OpenFrameworks): 0.041 sec   
11-13 13:35:57.413: I/OF(754): LastUpdateTime (High precision): 0.0353661 sec   
11-13 13:35:57.413: I/OF(754): TotalGameTime  (OpenFrameworks): 2394 ms   
11-13 13:35:57.413: I/OF(754): ElapsedGameTime (OF  deltaTime): 36 ms   
11-13 13:35:57.413: I/OF(754): ------------------------------------------   

  • ofGetLastFrameTime() reports a frametime of 41 ms
  • My measurements show 35~36 ms

Perhaps I don’t full understand what ofGetLastFrameTime() is suppose to be? I thought it was the time since the last render call ( time between two draw() calls). But apparently it is measured in some different way or it is measuring something else?

Windows log: http://falcon4ever.pcsx2.net/TimingWindows.txt

I also noticed this (this is part of the windows log):

  
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.033 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0839713 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 3933 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 84 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.192 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.212368 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 4145 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 212 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.151 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0833211 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 4228 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 83 ms   
OF: OF_LOG_NOTICE: ------------------------------------------   
OF: OF_LOG_NOTICE: LastFrameTime  (OpenFrameworks): 0.0370002 sec   
OF: OF_LOG_NOTICE: LastUpdateTime (High precision): 0.0339675 sec   
OF: OF_LOG_NOTICE: TotalGameTime  (OpenFrameworks): 4262 ms   
OF: OF_LOG_NOTICE: ElapsedGameTime (OF  deltaTime): 34 ms   
OF: OF_LOG_NOTICE: -----------------------------------------  

Random spikes to 80~200 ms. Is openframeworks pushing some events every X frames that is stalling the render/update loop?

So the timing internally was meassured using milliseconds, now it’s using microseconds.

Also there was an issue in android were the reported time was that of the previous frame not the current. I’ve uploaded a fix. Also in your code, it’s better if you do the time measurements and update of the animation in update instead of draw. With that i’m getting pretty much the same results as with your timing (internally OF is actually calling the same functions)

As for windows i prefer not to touch that part of the code since it affects several platforms and we’ve have problems before with it. Will take a look at some point and probably change it to microseconds too

Just applied your fixes and did another test: http://falcon4ever.pcsx2.net/TimingAndroidLogCatFixes.txt

Seems to work much better now :)!

  
  
11-13 15:43:33.929: I/OF(2276): ------------------------------------------   
11-13 15:43:33.969: I/OF(2276): LastFrameTime  (OpenFrameworks): 0.036891 sec   
11-13 15:43:33.969: I/OF(2276): LastUpdateTime (High precision): 0.03689 sec   
11-13 15:43:33.969: I/OF(2276): TotalGameTime  (OpenFrameworks): 1591 ms   
11-13 15:43:33.969: I/OF(2276): ElapsedGameTime (OF  deltaTime): 37 ms   
11-13 15:43:33.969: I/OF(2276): ------------------------------------------   
11-13 15:43:34.009: I/OF(2276): LastFrameTime  (OpenFrameworks): 0.036341 sec   
11-13 15:43:34.009: I/OF(2276): LastUpdateTime (High precision): 0.0363419 sec   
11-13 15:43:34.009: I/OF(2276): TotalGameTime  (OpenFrameworks): 1627 ms   
11-13 15:43:34.009: I/OF(2276): ElapsedGameTime (OF  deltaTime): 36 ms   
11-13 15:43:34.009: I/OF(2276): ------------------------------------------   
11-13 15:43:34.039: I/OF(2276): LastFrameTime  (OpenFrameworks): 0.036128 sec   
11-13 15:43:34.039: I/OF(2276): LastUpdateTime (High precision): 0.036128 sec   
11-13 15:43:34.039: I/OF(2276): TotalGameTime  (OpenFrameworks): 1663 ms   
11-13 15:43:34.039: I/OF(2276): ElapsedGameTime (OF  deltaTime): 36 ms   
11-13 15:43:34.049: I/OF(2276): ------------------------------------------   
11-13 15:43:34.079: I/OF(2276): LastFrameTime  (OpenFrameworks): 0.042348 sec   
11-13 15:43:34.079: I/OF(2276): LastUpdateTime (High precision): 0.042347 sec   
11-13 15:43:34.089: I/OF(2276): TotalGameTime  (OpenFrameworks): 1706 ms   
11-13 15:43:34.089: I/OF(2276): ElapsedGameTime (OF  deltaTime): 43 ms   
11-13 15:43:34.089: I/OF(2276): ------------------------------------------   
  

I also changed the code to this as you suggested:

  
//--------------------------------------------------------------  
void testApp::update() {  
	// Timing	  
	const float curPreciseGameTime = time();  
	  
	// Set time structure  
	gametime.LastFrameTime = ofGetLastFrameTime();  
	gametime.LastUpdateTime = curPreciseGameTime - prevPreciseGameTime;	  
	gametime.TotalGameTime = ofGetElapsedTimeMillis();  
	gametime.ElapsedGameTime = gametime.TotalGameTime - prevGameTime;  
  
	// Store values for next frame  
	prevPreciseGameTime = curPreciseGameTime;  
	prevGameTime = gametime.TotalGameTime;  
	  
	// Debug output  
	#if defined(ENABLE_LOG)  
		ofLog() << "LastFrameTime  (OpenFrameworks):" << gametime.LastFrameTime << "sec";  
		ofLog() << "LastUpdateTime (High precision):" << gametime.LastUpdateTime << "sec";  
		ofLog() << "TotalGameTime  (OpenFrameworks):" << gametime.TotalGameTime << "ms";  
		ofLog() << "ElapsedGameTime (OF  deltaTime):" << gametime.ElapsedGameTime << "ms";  
		ofLog() << "------------------------------------------";  
	#endif  
  
	// update()  
	if(clicked)  
	{  
		#if defined(ENABLE_OPENFRAMEWORKS_FRAMETIME)  
			moveCamera(movement * gametime.LastFrameTime * 1000, 0);	// using ofGetLastFrameTime()  
		#else  
			moveCamera(movement * gametime.LastUpdateTime * 1000, 0);	// using time() highres measurement  
		#endif  
	}  
}  
  
//--------------------------------------------------------------  
void testApp::draw() {	  
	glPushMatrix();	  
	glTranslatef(cameraPos.x, cameraPos.y, cameraPos.z);	// Set camera position "Game world"  
  
		// Draw squares  
		ofFill();  
		ofSetColor(128, 128, 128);		  
		for(int i = 0; i < 30; ++i)  
		{  
			if(i%5)  
				ofSetColor(0, 180, 0);	  
			else  
				ofSetColor(128, 128, 128);		  
			ofRect((150*i), 150, 75, 75);  
		}  
  
	glPopMatrix();  
  
	// Debug info  
	ofSetColor(0, 0, 0);		  
	ofDrawBitmapString("fps: " + ofToString((int)floor(ofGetFrameRate())), 10, 20);  
	#if defined(ENABLE_OPENFRAMEWORKS_FRAMETIME)  
		ofDrawBitmapString("using ofGetLastFrameTime()", 10, 35);  
	#else  
		ofDrawBitmapString("using time() highres measurement", 10, 35);  
	#endif  
}