SFML community forums

Help => General => Topic started by: Gan on January 09, 2013, 09:04:25 am

Title: Strangest sf::sleep bug
Post by: Gan 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.
Title: Re: Strangest sf::sleep bug
Post by: Laurent 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 (http://gafferongames.com/game-physics/fix-your-timestep/).
Title: Re: Strangest sf::sleep bug
Post by: Gan 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]
Title: Re: Strangest sf::sleep bug
Post by: Laurent 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.
Title: Re: Strangest sf::sleep bug
Post by: Gan 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.  :-\
Title: Re: Strangest sf::sleep bug
Post by: Laurent on January 10, 2013, 07:55:56 am
Hmmm... yep, there must be something really strange happening on your computer :-\
Title: Re: Strangest sf::sleep bug
Post by: cire 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.

Title: Re: Strangest sf::sleep bug
Post by: Nexus 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...
Title: Re: Strangest sf::sleep bug
Post by: Gan 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 (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 (https://gist.github.com/2056936)
I'm gonna try this implementation when I get to my PC.
Title: Re: Strangest sf::sleep bug
Post by: Laurent 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.
Title: Re: Strangest sf::sleep bug
Post by: binary1248 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 (http://en.wikipedia.org/wiki/Spurious_wakeup) 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 (http://download.microsoft.com/download/3/0/2/3027D574-C433-412A-A8B6-5E0A75D5B237/Timer-Resolution.docx).

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 ;).
Title: Re: Strangest sf::sleep bug
Post by: Laurent 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 ;)).
Title: Re: Strangest sf::sleep bug
Post by: Daddi 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?
Title: Re: Strangest sf::sleep bug
Post by: Laurent on February 18, 2013, 11:09:01 am
Does the proposed patch solve your problem?
Title: Re: Strangest sf::sleep bug
Post by: Daddi 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.
Title: Re: Strangest sf::sleep bug
Post by: Laurent on February 18, 2013, 07:55:29 pm
Quote
the same effect as opening chrome.
Which is? To solve the problem? (sorry, I don't really remember the begining of this discussion)
Title: Re: Strangest sf::sleep bug
Post by: Daddi on February 18, 2013, 11:07:28 pm
Yes, the moment the chrome browser starts, the bug seems to vanish.
Could it be, that chrome sets windows sleep-time temporarily down to 1 (instead of 15.6 which was named earlier) and back after it gets closed?
Title: Re: Strangest sf::sleep bug
Post by: Laurent on February 18, 2013, 11:10:51 pm
Quote
Could it be, that chrome sets windows sleep-time temporarily down to 1 (instead of 15.6 which was named earlier) and back after it gets closed?
I don't know. It could be, yes.
Title: Re: Strangest sf::sleep bug
Post by: cire on February 19, 2013, 08:16:31 am
It would seem that it does.

Some interesting info here (http://www.belshe.com/2010/06/04/chrome-cranking-up-the-clock/).
Title: Re: Strangest sf::sleep bug
Post by: Daddi on February 19, 2013, 10:33:44 am
Thats very intersting! But I wonder, why this doesn't happen on every windows machine. At home, everythings fine, at work -> sleep "bug".
Title: Re: Strangest sf::sleep bug
Post by: Foaly on February 19, 2013, 10:55:49 am
Wow this is a very interesting article! So using timeBeginPeriod(1); seems to be quiet common for using high resolution timer/sleep.
Title: Re: Strangest sf::sleep bug
Post by: Daddi on February 19, 2013, 11:33:20 am
The earlier posted fix sets timeBeginPeriod every time before a single sleep is engaged. A better solution may be to do this once during the initialization of the application.
Title: Re: Strangest sf::sleep bug
Post by: binary1248 on February 23, 2013, 02:06:59 am
So that when the application terminates in some undefined way, the system gets stuck in high resolution mode? Changing the mode does not incur that much of a performance penalty and since it is used during sf::Sleep, whether that time is spent setting the mode or sleeping doesn't really matter.
Title: Re: Strangest sf::sleep bug
Post by: Daddi on February 25, 2013, 06:15:41 pm
True, I didn't think of this. But theoretically, this could happen with chrome too :)
Title: Re: Strangest sf::sleep bug
Post by: Foaly on July 29, 2013, 08:37:15 pm
Im sorry for reactivating this old topic. I know it's not a good practice, but since there where quiet a few topics recently about sf::sleep being a bit off (for example through setFramerateLimit() ) I remembered this thread. I dug it up and saw that there was quiet a lot of information gathered and even a solution proposed, but the problem was never actually solved. So shouldn't we investigate further or at least create a ticket on the tracker?
Title: Re: Strangest sf::sleep bug
Post by: eXpl0it3r on July 29, 2013, 09:09:05 pm
So shouldn't we investigate further or at least create a ticket on the tracker?
Hehe, I was thinking the same, but didn't go looking for the thread. Would be nice if we can find a good solution. :)
Title: Re: Strangest sf::sleep bug
Post by: Foaly on July 29, 2013, 10:30:37 pm
Hehe, I was thinking the same, but didn't go looking for the thread. Would be nice if we can find a good solution. :)
Good to hear! So I am not the only one :) I created an issue on the tracker: #439 (https://github.com/SFML/SFML/issues/439)
Title: Re: Strangest sf::sleep bug
Post by: Cornstalks on July 30, 2013, 02:58:27 pm
Hehe, I was thinking the same, but didn't go looking for the thread. Would be nice if we can find a good solution. :)
Good to hear! So I am not the only one :) I created an issue on the tracker: #439 (https://github.com/SFML/SFML/issues/439)
I personally think a "high resolution sleep" is a bad idea, as it's very platform dependent, and on some platforms completely impossible.

I think instead something that yield's the current thread's timeslice back to the system would be much more effective. (i.e. SwitchToThread() on Windows (not Sleep(0), which is different)); this would be most useful for programs that don't want to unnecessarily max out the CPU (like mobile devices, where battery is important).