cinder / Cinder

Cinder is a community-developed, free and open source library for professional-quality creative coding in C++.
http://libcinder.org
Other
5.32k stars 939 forks source link

ci::Timer sometimes runs backwards on OSX #1205

Open sansumbrella opened 8 years ago

sansumbrella commented 8 years ago

I noticed this when using the Cinder-ImGui block, which has an assert that delta time is non-negative. When an application was left running overnight and the computer went to sleep, the ImGui assertion failed. I was unable to reproduce simply by adjusting the computer's clock or by putting to sleep and waking while debugging.

It seems likely that it is somehow related to app nap and/or computer sleep. Hopefully I will be able to trigger it while I'm watching someday.

sansumbrella commented 8 years ago

A simple test app that may be useful for debugging follows.

#include "cinder/app/App.h"
#include "cinder/app/RendererGl.h"
#include "cinder/gl/gl.h"
#include "cinder/Log.h"

using namespace ci;
using namespace ci::app;
using namespace std;

class TimerTestApp : public App {
  public:
    void setup() override;
    void update() override;
    void draw() override;
  private:
    ci::Timer mTimer;
    double      mLastTime = 0.0;
    bool            mHasGoneBackwards = false;
};

void TimerTestApp::setup()
{
    log::LogManager::instance()->makeLogger<log::LoggerSystem>();
}

void TimerTestApp::update()
{

    const auto now = getElapsedSeconds();
    const auto delta = now - mLastTime;

    if( delta < 0.0 ) {
        CI_LOG_E( "Elapsed seconds delta was negative. " << delta << ", " << now );
        mHasGoneBackwards = true;
    }

    static ci::Timer sTimer( true );
    const auto staticSeconds = sTimer.getSeconds();
    sTimer.start();

    if( staticSeconds < 0.0 ) {
        CI_LOG_E( "Static second count was negative. " << staticSeconds << ", " << now );
        mHasGoneBackwards = true;
    }

    const auto memberSeconds = mTimer.getSeconds();
    mTimer.start();

    if( memberSeconds < 0.0 ) {
        CI_LOG_E( "Member second count was negative. " << memberSeconds << ", " << now );
        mHasGoneBackwards = true;
    }

    mLastTime = now;
}

void TimerTestApp::draw()
{
    gl::clear( Color( 0, 0, 0 ) );
    if( mHasGoneBackwards ) {
        gl::ScopedColor color(Color(1.0f, 0.0f, 0.0f));
        gl::drawSolidCircle(getWindowCenter(), getWindowHeight() * 0.5f);
    }
}

CINDER_APP( TimerTestApp, RendererGl )
chaoticbob commented 8 years ago

If anyone is testing this, it would be nice if you could post the logs of the time deltas so we can see how large the deltas are.

sansumbrella commented 8 years ago

I'm leaving one on right now and hoping something happens overnight.

paulhoux commented 8 years ago

Sounds like an integer overflow, but it surprises me that it happens within 24 hours. I remember that when counting milliseconds using a signed integer, it overflows after 25 days or so. What are we counting in the Timer class? Parsecs? Lightyears? ;)

paulhoux commented 8 years ago

From the docs: (https://developer.apple.com/library/prerelease/ios/documentation/CoreFoundation/Reference/CFTimeUtils/index.html#//apple_ref/c/func/CFAbsoluteTimeGetCurrent)

Absolute time is measured in seconds relative to the absolute reference date of Jan 1 2001 00:00:00 GMT. A positive value represents a date after the reference date, a negative value represents a date before it. For example, the absolute time -32940326 is equivalent to December 16th, 1999 at 17:54:34. Repeated calls to this function do not guarantee monotonically increasing results. The system time may decrease due to synchronization with external time references or due to an explicit user change of the clock.

sansumbrella commented 8 years ago

Thanks for looking that up, @paulhoux! It goes backward by design.

Should probably just file a PR on the gui block to set it to zero if the delta is negative.

sansumbrella commented 8 years ago

Closing since its part of the underlying system implementation. But could be a gotcha if you aren't clamping your timesteps to a positive range.

paulhoux commented 8 years ago

Well, maybe keep it open because there might be a better alternative instead of relying on the system clock. On Windows, we simply count the ticks (100-nanoseconds). Isn't there something similar on the Mac?

paulhoux commented 8 years ago

Reading this now: https://developer.apple.com/library/ios/technotes/tn2169/_index.html

Edit: looks like mach_absolute_time might be a good candidate? https://developer.apple.com/library/mac/qa/qa1398/_index.html

Edit 2: doh, that's similar.