Welcome, Guest. Please login or register. Did you miss your activation email?

Author Topic: Strangest sf::sleep bug  (Read 15995 times)

0 Members and 1 Guest are viewing this topic.

Gan

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Strangest sf::sleep bug
« on: January 09, 2013, 09:04:25 am »
In my program I couldn't help noticing that the server was lagging behind the client. I have the server hosted on my pc machine and client on my mac.
CPU usage of the PC was 1% so I decided to track the main logic loop's FPS.
I have the sleep method set to 60 frames per second, but using the sf::clock I was able to see that the method was only running at half the speed. 30 frames per second.
I couldn't figure what in my code would cause such a delay. Then I got the idea to clock the sleep method itself. Turns out the sleep method was sleeping for twice as long as it was told to.

So I opened Google Chrome and went searching for an answer. I looked back at my debug console, and suddenly it was spitting out 60 fps instead of the 30. Perplexed, I closed Google Chrome and boom, back down to 30fps.
I re-opened Google Chrome, 60 fps. Closed Google Chrome, 30 fps.

I am unsure about the correlation between Google Chrome and the sf::sleep function... but right now it's an easy fix by just doubling my FPS to 120 so that it runs at 60fps (with Google Chrome closed).

My sleep code:
Code: [Select]
sf::sleep(sf::seconds(1.0f/fps));fps is a const float defined as 60.

If I'm not doing something blatantly wrong, I can provide further information. (Video, full source code, ect)

Edit:
On the plus side this bug has allowed me to make a stabilization formula that generates an FPS ratio dynamically to heighten or lower the sleep amount to produce an equal time step for the physics simulation. Thus keeping the client and server in sync wether the sleep function is malfunctioning or the burden of a heavy load is overtaking.
« Last Edit: January 09, 2013, 09:30:42 am by Laurent »

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #1 on: January 09, 2013, 09:33:51 am »
This is really strange and I have no idea what's wrong. If you could provide a complete and minimal code that reproduces the problem, that would help a lot.

By the way, using sf::sleep to implement an accurate fixed timestep is not recommended. You should read this popular article: fix your timestep.
Laurent Gomila - SFML developer

Gan

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Strangest sf::sleep bug
« Reply #2 on: January 09, 2013, 10:15:49 am »
I've attached the source below. Here's the code without having to unzip the source:
Code: [Select]
#include <SFML/Graphics.hpp>
#include <iostream>

const float fps = 60;
const bool autoFpsFixer = false;

int main (int argc, const char * argv[])
{
sf::RenderWindow window(sf::VideoMode(800, 600), "Server");
float fpsRatio = 1.0;
sf::Clock fpsClock;
while (window.isOpen())
{
window.clear();
window.display();

        sf::sleep(sf::seconds(1.0f/fps*fpsRatio));

        float fpsAmount = (1.0/fpsClock.restart().asSeconds());
        if (autoFpsFixer) { //Enable to make the fps fix itself
            fpsRatio -= 1.0-(fpsAmount/fps);
        }

        std::cout << "FPS: " << fpsAmount << " vs " << fps << " sleep amount: " << 1.0f/fps*fpsRatio <<  std::endl;
}

    return EXIT_SUCCESS;
}

This code produces the output:
Quote
[debug]FPS: 32.0051 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9969 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9795 vs 60 sleep amount: 0.0166667
[debug]FPS: 32.0215 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9714 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9724 vs 60 sleep amount: 0.0166667
[debug]FPS: 32.0544 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9959 vs 60 sleep amount: 0.0166667
[debug]FPS: 32.0041 vs 60 sleep amount: 0.0166667
[debug]FPS: 32 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.999 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9785 vs 60 sleep amount: 0.0166667
[debug]FPS: 31.9918 vs 60 sleep amount: 0.0166667
[debug]FPS: 32.0184 vs 60 sleep amount: 0.0166667
FPS is the fps I'm getting, sleep amount is the amount it should be sleeping to be 60fps but isn't.

[attachment deleted by admin]
« Last Edit: January 09, 2013, 10:17:33 am by Gan »

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #3 on: January 09, 2013, 08:53:14 pm »
Your code doesn't account for time spent to execute one iteration of the loop: your frame time is 1/60 plus the loop time -- which is significant, since writing stuff to the console is really slow.

Counting the number of frames drawn in 1 second and printing it every second is a better algorithm if you don't want to disturb the results. Or even better: use an external tool like FRAPS.
Laurent Gomila - SFML developer

Gan

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Strangest sf::sleep bug
« Reply #4 on: January 10, 2013, 12:27:17 am »
Ah good idea.
I just re-did the code to print out the average FPS every 101 frames.
Code: [Select]
#include <SFML/Graphics.hpp>
#include <iostream>

const float fps = 60;

float frames = 0;

int main (int argc, const char * argv[])
{
sf::RenderWindow window(sf::VideoMode(800, 600), "Server");
float fpsRatio = 1.0;
sf::Clock fpsClock;
while (window.isOpen())
{
window.clear();
window.display();

        sf::sleep(sf::seconds(1.0f/fps));

        frames += 1;
        if (frames > 100) {
            std::cout << "FPS: " << (1.0/(fpsClock.restart().asSeconds()/frames)) << " vs " << fps <<  std::endl;
            frames = 0;
        }
}

    return EXIT_SUCCESS;
}

Here's the output:
Quote
Child process PID: 2976

[debug][New Thread 2976.0xfb0]
[debug][New Thread 2976.0x13c4]
[debug][New Thread 2976.0x13b0]
[debug][New Thread 2976.0x414]
[debug][New Thread 2976.0x314]
[debug][New Thread 2976.0x1324]
[debug]FPS: 59.8948 vs 60
[debug]FPS: 60.2346 vs 60
[debug]FPS: 60.2345 vs 60
[debug]FPS: 60.2345 vs 60
[debug]FPS: 60.2345 vs 60
[debug]FPS: 60.2345 vs 60
[debug]FPS: 60.2346 vs 60
[debug]FPS: 60.2345 vs 60
[debug]FPS: 60.2294 vs 60
[debug]FPS: 40.4556 vs 60
[debug]FPS: 31.9996 vs 60
[debug]FPS: 32.0001 vs 60
[debug]FPS: 31.9991 vs 60
[debug]FPS: 31.9993 vs 60
The output looked fantastic, until I realized Google Chrome was open. Closed it and FPS dropped back down to the usual.

Perhaps there's just something wrong with my computer.  :-\

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #5 on: January 10, 2013, 07:55:56 am »
Hmmm... yep, there must be something really strange happening on your computer :-\
Laurent Gomila - SFML developer

cire

  • Full Member
  • ***
  • Posts: 138
    • View Profile
Re: Strangest sf::sleep bug
« Reply #6 on: January 10, 2013, 09:07:48 am »
I believe it has to do with the granularity of sf::sleep on your system.  (Mine behaves in a similar way.)

On my system, the granularity of sleep is about 14ms.  1/60 is about 16ms, so depending on the timing sleeping for 1/60 of a second can sleep for ~2 ~2/60 seconds, which leads to an average of a little over 30 fps.   If I sleep for 1/120 of a second, I get a little over 60 fps, and as expected, if I sleep for 1/240th of a second, I also get a little over 60 fps.

« Last Edit: January 10, 2013, 09:21:35 pm by cire »

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6286
  • Thor Developer
    • View Profile
    • Bromeon
Re: Strangest sf::sleep bug
« Reply #7 on: January 10, 2013, 09:29:31 am »
I have already encountered a similar strange issue: http://en.sfml-dev.org/forums/index.php?topic=7750

Since then, I haven't investigated it any further...
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

Gan

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Strangest sf::sleep bug
« Reply #8 on: January 10, 2013, 08:10:42 pm »
I wonder if there's a way to increase sleep precision....

I've found this function: std::this_thread::sleep_for, but I think it's probably nearly the same as the win32 function already used. (I can give it a try anyway)
Besides that, there's the Boost Chrono library that looks interesting.

Just found this article: http://stackoverflow.com/questions/1487695/c-cross-platform-high-resolution-timer
One person's implementation is quite interesting. (Though not portable across different CPUs) It hardwires directly into the machine's clock and can get a precision of 6 nanoseconds.

Just found some more code regarding high precision, cross compatible, c++11 sleeping:
https://gist.github.com/2056936
I'm gonna try this implementation when I get to my PC.

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #9 on: January 10, 2013, 08:37:49 pm »
High resolution cloks are not hard to get on every OS. High resolution sleep is a totally different story, it depends on the time slice that the OS scheduler allocates to threads, and this is usually not something that you can modify, it's a very low-level setting. As far as I know, on Linux you need to recompile the kernel to change that, and on Windows I think it's impossible.
Laurent Gomila - SFML developer

binary1248

  • SFML Team
  • Hero Member
  • *****
  • Posts: 1405
  • I am awesome.
    • View Profile
    • The server that really shouldn't be running
Re: Strangest sf::sleep bug
« Reply #10 on: January 11, 2013, 06:35:31 am »
I just had a look at the implementations of the Sleep functions for both Win32 and Unix.

Even though it probably has nothing directly to do with this thread, the implementation of Sleep in Unix was sort of... broken in specific cases ;). When using pthread_cond_wait or pthread_cond_timedwait, one has to be aware of the evil spurious wakeups that can occur. They are supposed to be a rare occurrence, but if for some reason on some system they happen more than expected, using sf::Sleep is like taking part in a lottery :). To fix this, either you evaluate the condition every time the function returns or you reimplement Sleep without using it (which is what I did). In the comments you mentioned that usleep is unreliable and might put the entire process to sleep but usleep also isn't part of POSIX any more, I guess because it was that horrible. Instead you can use nanosleep which is part of POSIX as well and should be better supported on all compatible platforms.

For the Win32 implementation,
... and on Windows I think it's impossible.
this is only partially true. On Windows you can set the timer resolution to whatever you want within the system specified limits. On my system this is anything from 1ms to 1000000ms. According to Microsoft they implemented it like this originally to save energy and increase system responsiveness. Now with the new timer coalescing API it got a bit more complicated but that isn't something we have to worry about. Fact is that the default timer resolution on Windows systems is not 1ms but e.g. on Windows 7 15.6ms. The problem arrises when a user calls sf::Sleep with values that don't fit into this interval nicely. You can read more about this in this Microsoft document.

If you call sf::Sleep with a value of 1ms in my tests Windows will almost always sleep for 15.6ms instead, so calling sf::Sleep( sf::milliseconds( 1 ) ); 1000 times actually puts the thread to sleep for 15.6 seconds instead of 1 second. It seems that Windows likes to round the sleep times up but also rounds down sometimes. If you sleep for some value that is a multiple of 15.6ms then everything behaves as you would expect.

So in essence if you want to lock your application at 60 FPS, you tell SFML to sleep for 1/60 seconds which is 16.6ms. If you are lucky, this is close enough to 15.6ms that it doesn't have any adverse side effects on your application. However if you are not so lucky it is rounded up to 31.2ms which causes your application to run at half the desired frame rate. I assume this is happening here. In order to force Windows to obey your desired frame rate up to 1000 FPS you would need to set the timer resolution to 1ms which is what I did and everything worked nicely. Anything above 1000 FPS and Windows can't handle it because 1ms is the lowest resolution available (but seriously, why would you set the limit to something above 1000 FPS? ::))

So at the default resolution of 15.6ms on Windows 7 sf::Sleep can only be truly accurate at 64, 32, 16... FPS. In extreme cases (such as is the case here) where you deviate from those values only just a bit Windows locks you at the next lower frame rate.

Here you can test sf::Sleep with and without timeBeginPeriod().
#include <iostream>
#include <SFML/System.hpp>
#include <windows.h>

int main() {
        //timeBeginPeriod( 1 );

        {
                sf::Clock clock;

                for( int i = 0; i < 1000000; i++ ) {
                        sf::sleep( sf::microseconds( 1 ) );
                }

                std::cout << clock.getElapsedTime().asMilliseconds() << "ms\n";
        }

        {
                sf::Clock clock;

                for( int i = 0; i < 1000; i++ ) {
                        sf::sleep( sf::milliseconds( 1 ) );
                }

                std::cout << clock.getElapsedTime().asMilliseconds() << "ms\n";
        }

        {
                sf::Clock clock;

                for( int i = 0; i < 1000/15; i++ ) {
                        sf::sleep( sf::milliseconds( 15 ) );
                }

                std::cout << clock.getElapsedTime().asMilliseconds() << "ms\n";
        }

        {
                sf::Clock clock;

                for( int i = 0; i < 1; i++ ) {
                        sf::sleep( sf::seconds( 1 ) );
                }

                std::cout << clock.getElapsedTime().asMilliseconds() << "ms\n";
        }

        //timeEndPeriod( 1 );

        return 0;
}
 

The changes I made to the library can be found here: https://github.com/binary1248/SFML/commit/20db4969c59c06c4605473fc8f36ad7e5859453b

Setting timeBeginPeriod to 1 might increase power consumption when running an SFML application that uses sf::Sleep but this is negligible because the high-resolution timers do this already anyway. It's never too late to contribute to global warming in your own special way ;).
« Last Edit: January 11, 2013, 06:42:25 am by binary1248 »
SFGUI # SFNUL # GLS # Wyrm <- Why do I waste my time on such a useless project? Because I am awesome (first meaning).

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #11 on: January 11, 2013, 08:01:32 am »
Thanks for the patches.

I never realized that timeBeginPeriod could have an effect on the thread scheduler, I thought it was only for multimedia timers. But I don't know if it's a clean solution, to me it's more a side effect: the description says "requests a minimum resolution for periodic timers", and in the remarks they say "However, it can also reduce overall system performance, because the thread scheduler switches tasks more often. High resolutions can also prevent the CPU power management system from entering power-saving modes".

If I have time I'll search more information on that.

I'll also check if nanosleep is that different from usleep, and change the implementation accordingly if you're right (and I'm sure you are ;)).
Laurent Gomila - SFML developer

Daddi

  • Jr. Member
  • **
  • Posts: 66
    • View Profile
    • http://foxdev.de/
    • Email
Re: Strangest sf::sleep bug
« Reply #12 on: February 18, 2013, 10:50:59 am »
I encountered the same problem but just since I use Windows 8 at home. Could this be a reason for this bug?

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32504
    • View Profile
    • SFML's website
    • Email
Re: Strangest sf::sleep bug
« Reply #13 on: February 18, 2013, 11:09:01 am »
Does the proposed patch solve your problem?
Laurent Gomila - SFML developer

Daddi

  • Jr. Member
  • **
  • Posts: 66
    • View Profile
    • http://foxdev.de/
    • Email
Re: Strangest sf::sleep bug
« Reply #14 on: February 18, 2013, 01:30:15 pm »
I didn't try it yet but tonigt I will compile the sources and report the results

Edit:
Just using timeBeginPeriod(1) and timeEndPeriod(1) before/after the sleep command has the same effect as opening chrome.
« Last Edit: February 18, 2013, 01:49:39 pm by Daddi »