sf::Time getCurrentTime fails on certain systems

[slotdev]

I have a strange bug where every clock object goes negative, on certain systems, but not all the time.

I think the problem could be with QueryPerformanceCounter in ClockImpl.cpp. This function can fail on some systems, and because the variable used to store the time is declared locally to the function, it could be any number.

Latest version of SFML has this in ClockImpl.cpp:

    HANDLE currentThread = GetCurrentThread();
    DWORD_PTR previousMask = SetThreadAffinityMask(currentThread, 1);

    // Get the frequency of the performance counter
    // (it is constant across the program lifetime)
    static LARGE_INTEGER frequency = getFrequency();

    // Get the current time
    LARGE_INTEGER time;
    QueryPerformanceCounter(&time);

    // Restore the thread affinity
    SetThreadAffinityMask(currentThread, previousMask);

    // Return the current time as microseconds
    return sf::microseconds(1000000 * time.QuadPart / frequency.QuadPart);
 

Previous versions had this (in Platform.cpp - before it got moved around):

    static LARGE_INTEGER frequency;
    static BOOL          useHighPerformanceTimer = QueryPerformanceFrequency(&frequency);

    if (useHighPerformanceTimer)
    {
        // High performance counter available : use it
        LARGE_INTEGER currentTime;
        QueryPerformanceCounter(&currentTime);

        return currentTime.QuadPart * 1000 / frequency.QuadPart;
    }
    else
    {
        // High performance counter not available: use GetTickCount (less accurate)
        return GetTickCount();
    }
 

So at least if the QueryPerformanceFrequency failed, GetTickCount would be a backup in this case, and not return an unknown value as the current implementation will do.

Is this a bug, or have I misunderstood?

Regards
Ed

[Laurent]

The performance counter is known to produce inconsistent results sometimes (type "QueryPerformanceCounter bug" in Google, there is a huge number of relevant results).

The thread affinity hack is supposed to fix these inconsistencies though, so I don't know why you keep getting strange results.

Testing the availability of the performance counter like before wouldn't help: either it is always supported or not at all (look at the boolean, it is a static variable, which means that the test is done only once, on the very first call). And with todays machines/OSes, the performance counter is always supported, therefore the test is useless.

[slotdev]

Interesting. It seems the system we're having problems (XP Embedded) with does support QueryPerformanceCounter. I've just added the following code to see what difference it makes. I suspect that QueryPerformanceCounter was still failing, but I can't be sure yet.

Time ClockImpl::getCurrentTime()
{
    // Force the following code to run on first core
    // (see http://msdn.microsoft.com/en-us/library/windows/desktop/ms644904(v=vs.85).aspx)
    HANDLE currentThread = GetCurrentThread();
    DWORD_PTR previousMask = SetThreadAffinityMask(currentThread, 1);

    // Get the frequency of the performance counter
    // (it is constant across the program lifetime)
    static LARGE_INTEGER frequency = getFrequency();

    // Get the current time
    LARGE_INTEGER time;
    QueryPerformanceCounter(&time);

    // Restore the thread affinity
    SetThreadAffinityMask(currentThread, previousMask);
        sf::Time myTime = sf::microseconds(1000000 * time.QuadPart / frequency.QuadPart);
        if (myTime.asMicroseconds() < 0)
        {
                return sf::microseconds(1000 * GetTickCount());
        }
    // Return the current time as microseconds
    return sf::microseconds(1000000 * time.QuadPart / frequency.QuadPart);
}
 

[Laurent]

So what's the result of falling back to GetTickCount() when QPF returns a negative time? Does it solve all your problems?

By the way:

sf::microseconds(1000 * GetTickCount());

-->

sf::milliseconds(GetTickCount());

[slotdev]

After more testing, it seems there is something else going on. Using GetTickCount or not, makes no difference. So I guess QPF, etc, are actually OK.

I can initialise 20 timers, and as soon as 1 timer is negative, all 20 will also be negative. So I guess I am getting memory corruption somehow. I chose timer 9 as my "main" timer for this test. All others have a very similar value........

: TIMER 00 = -4120139
: TIMER 01 = -4120123
: TIMER 02 = -4120107
: TIMER 03 = -4120092
: TIMER 04 = -4120076
: TIMER 05 = -4120029
: TIMER 06 = -4119998
: TIMER 07 = -4119982
: TIMER 08 = -4119951
: TIMER 09 = -4285138
: TIMER 10 = -4119904
: TIMER 11 = -4119889
: TIMER 12 = -4119873
: TIMER 13 = -4119857
: TIMER 14 = -4119842
: TIMER 15 = -4119826
: TIMER 16 = -4119795
: TIMER 17 = -4119779
: TIMER 18 = -4119764
: TIMER 19 = -4119732
 

[Laurent]

Are you testing sf::Clock in a new minimal program, or in your big application? If not already done, you should try the first option, to make sure that the bug is caused by SFML and not by your own code.

[slotdev]

I'm going to try that next. My guess is that it's not an SFML problem; we'd have seen reports about this on the forum before

[slotdev]

OK, it still happens in a minimal program.

int _tmain(int argc, _TCHAR* argv[])
{
        sf::Clock testTimer;
    sf::RenderWindow window1(sf::VideoMode(   0,    0,100,100),"Test1",sf::Style::None);

        testTimer.restart();

        while (window1.isOpen())
    {
        if (sf::Keyboard::isKeyPressed(sf::Keyboard::Escape))
                {
            window1.close();
                }
        sf::Event event;
        while (window1.pollEvent(event))
        {
            if (event.type == sf::Event::Closed)
                window1.close();
        }
                if (testTimer.getElapsedTime().asMilliseconds() > 1000)
                {
                        testTimer.restart();
                }
                if (testTimer.getElapsedTime().asMilliseconds () < 0)
                {
                        FILE *myFile = fopen("timer.log","w"); 
                        int fault = 1;
                        fprintf(myFile,"Timer went negative, value is %d, last error: %d",testTimer.getElapsedTime().asMilliseconds(),GetLastError());
                        fclose(myFile);
                        return 0;
                }
                sf::sleep(sf::milliseconds(1));
        }
    return 0;

}
 

I forgot to get the error code...I'm running it again now. It might take a while for it to go wrong (last time was approx. 20 mins, it's been running over 1.5hrs now and still OK...).

[slotdev]

After running for ~2 hours: Timer went negative, value is -6916767, last error: 0

Tomorrow's task: download latest SFML snapshot and run test again.

[slotdev]

OK, so the latest SFML snapshop has the same issue. I think this is limited to certain hardware however, as it has never occured on my desktop PC. I would be interested to see others try the minimal example I supplied, as I am sure this will happen on other systems (as it does on one hardware platform we use, in particular).

Warning: it can take 6+ hours to happen.

I have had to "fix" this problem by ensuring sf::Time uses unsigned variables, so the time can never go negative. If there is a problem, then at least the time will (probably) be a massive number and thus when I check my timers, it will just think a big amount of time has passed, and in my case this fails safe. The same might not be true for others.

For reference, the system I have problems on is a Windows XP embedded platform, running a 2.2GHz Intel processor with 2GB RAM.