[bug] ofGetLastFrameTime() always returns 0

[artificiel]

on macOS14 with current OF-git, doing this always prints 0:

void ofApp::update(){
	ofLogNotice("last") << ofGetLastFrameTime();
}

[notice ] last: 0.0
[notice ] last: 0.0
[notice ] last: 0.0
[notice ] last: 0.0

perhaps it's local to macOS — could other platforms confirm?
if it's really a regression it's traceable to #7966 and reverting it fixes the problem:

[notice ] last: 0.00400008
[notice ] last: 0.0123949
[notice ] last: 0.00437546
[notice ] last: 0.0117662

[danoli3]

Can confirm Visual Studio 2022 / Windows so all platforms affected.

I noticed this ages ago although was convinced it was a local project issue and forgot as I fixed with (in setup):

ofSetFrameRate(60);
ofSetTimeModeFixedRate(ofGetFixedStepForFps(60));

[danoli3]

Okay to assist debugging:

Problem only occurs on System.

Example failing: code (update)

float timeFromLast = ofGetLastFrameTime();
currentTime += timeFromLast;

ofLog(OF_LOG_NOTICE) << "ofGetLastFrameTime:[" << timeFromLast << "] currentFadeIn:" << currentFadeIn << " < fadeInTotal:[" << fadeInTotal << "]";
if(isFadedIn == false) {
 if(currentFadeIn >= fadeInTotal) {
     isFadedIn = true;
		ofLog(OF_LOG_NOTICE) << "FadedIn timeFromLast:" << timeFromLast;
 }
 }

Logs:

[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0] currentFadeIn:0 < fadeInTotal:[0.417]

Expected:

[notice ] ofxSplash: setup (filtered 120 fps)
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.00833333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0166667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.025 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0333333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0416667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.05 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0583333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0666667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.075 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0833333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.0916667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.1 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.108333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.116667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.125 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.133333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.141667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.15 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.158333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.166667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.175 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.183333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.191667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.2 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.208333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.216667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.225 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.233333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.241667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.25 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.258333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.266667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.275 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.283333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.291667 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.3 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.308333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.316666 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.325 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.333333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.341666 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.35 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.358333 < fadeInTotal:[0.417]
[notice ] ofGetLastFrameTime:[0.00833333] currentFadeIn:0.366666 < fadeInTotal:[0.417]

Change (in setup):

ofSetFrameRate(120);
ofSetTimeModeFixedRate(ofGetFixedStepForFps(120));

Problem code:

//--------------------------------------
double ofCoreEvents::getLastFrameTime() const {
	switch (timeMode) {
	case Filtered:
		return fps.getLastFrameFilteredSecs();
	case FixedRate:
		return std::chrono::duration<double>(fixedRateTimeNanos).count();
	case System:
	default:
		return fps.getLastFrameSecs();
	}
}

Case System is problem.

First frame:

Frame10:

now = {_MyDur=1319413556635400 nanoseconds }
then = {_MyDur=1319413556635400 nanoseconds }
lastFrameTime = 8224500 nanoseconds
diff = 0 nanoseconds
fps = 10.000000000000000

[danoli3]

@dimitre I did some extra debugging here: https://github.com/openframeworks/openFrameworks/compare/master...danoli3:openFrameworks:timerFixes?expand=1

[artificiel]

hey @danoli3 great that you can debug a bit but until the situation is resolved, how about reverting the PR, as it breaks things namely ofxFileWatch, and coming back to an existing/working project it took me a while to figure out why file changes stopped triggering the expected events...

/master should not be left in a known defect state.

[danoli3]

@artificiel yeah agreed, since time slice is so important for movement of objects. I always use FixedRate though so bypassing this bug.

I had another look and made some ammendments for speed, optimisation and fixed the whole problem: was using a duration_cast instead of a std::chrono::duration(filteredTime).count();

Fixed Queue to Deque so we can allocate size for FPS fix memory up and down with variable FPS anomolies causing memory realloc movement. Only calculate filtered time if in filteredMode as added clamps to fix anomalies detected,

[danoli3]

All fixed @artificiel no need to revert, the functionality add is good, just some casting issues and initialisation problems it looked like in the end.