getStatus() Waits for SF::Music to Load - Pauses Program 80ms

[Acumen]

So I was trying to figure out why I was having a weird hiccup in my program and figured out it was from calling getStatus() on an SF::Music shortly after calling play(). It takes almost 80ms which is obviously noticeable.

Is there a best practice (single thread) work around for this? Delaying checking the status an arbitrary amount of time hoping the stream has loaded seems weird. Any other way to see if the file is loaded enough to be able to check it's status?

It would be nice if getStatus() returned -1 or something if the stream has not loaded yet instead of hanging.

Edit: Also noticed calling stop() takes about 5ms?! Is that the case for everyone? Is that much time really needed? Huge overhead there I never realized.

[Laurent]

First, make sure that you test the latest sources, things have changed in sf::SoundStream since SFML 2.1.

I can imagine why stop() takes a few milliseconds: it waits for the streaming thread to stop, and there can be some delay because of the resolution of the sf::sleep function (caused by the OS scheduler).

However there's no reason for getStatus() to take that long. It only calls the corresponding OpenAL function. So if there's something wrong here, it's not in SFML. Could you try to reproduce this behaviour in a complete and minimal code?

[Acumen]

So I was using a recent snapshot, but just built with the latest source (files time-stamped Nov 5 11:36) and the problem is still there. Key clue I figured out, the problem is not there when built against 2.1 libs, so it must have been introduced recently or I am doing something wrong with the new format that has not affected anything else.

#include <SFML/Audio.hpp>
#include <iostream>

int main(int argc, char *argv[])
{
        sf::Clock clock;
        sf::Music music;
        music.openFromFile("test.ogg");

        std::cout<<"TIME 1: "<<clock.getElapsedTime().asMilliseconds()<<'\n';
        music.play();
        std::cout<<"TIME 2: "<<clock.getElapsedTime().asMilliseconds()<<'\n';
        music.getStatus();
        std::cout<<"TIME 3: "<<clock.getElapsedTime().asMilliseconds()<<'\n';
        int x = 0;
        std::cin>>x;
        return(0);
}

Output:

TIME 1: 80
TIME 2: 80
TIME 3: 108

[Laurent]

So it's 28 ms, not 80

If you want to help, you can have a look at the git log for SoundStream.cpp and Music.cpp files (between 2.1 and now), try revisions that make significant changes to these classes, and hopefully find the commit which introduces this behaviour. There shouldn't be a lot of commits to test.

[Acumen]

Ah that could be another useful symptom, I do get ~80ms in my main project so it is variable somehow. I will poke around.

Are you able to reproduce the delay at all? I worry it could be me doing something stupid in my dependencies.

[Nexus]

He meant that to measure the time for the getStatus() call, you need to subtract the second from the third time, as you don't reset the clock. That's why 108 - 80 = 28.

Your measurement is flawed. The problem is the std::cout statement, which takes quite long. Measure it like this:

        sf::Clock clock;
        music.openFromFile("orchestral.ogg");
        sf::Time a = clock.restart();
        music.play();
        sf::Time b = clock.restart();
        music.getStatus();
        sf::Time c = clock.restart();

        std::cout << "openFromFile: " << a.asMicroseconds() << "us\n";
        std::cout << "play:         " << b.asMicroseconds() << "us\n";
        std::cout << "getStatus:    " << c.asMicroseconds() << "us\n";

I get ~5000us (openFromFile), ~550us (play), ~10us (getStatus), respectively.

[Acumen]

I understand it was 28ms here, I was getting 80ms in my actual project. Which seems pretty crazy to me which was I guess why I didn't think of it. 28ms-80ms for a cout statement!?

I think there may be some sort of weird conflict still going on here that shouldn't be? Some sort of threading issue? Check this example out, I still get a delay in getStatus:

#include <SFML/Audio.hpp>
#include <iostream>

int main(int argc, char *argv[])
{
        sf::Music music;
        music.openFromFile("test.ogg");
       
        sf::Clock clock;

        sf::Time a = clock.restart();
        music.play();
        std::cout<<"COUT STATEMENT\n";
        sf::Time b = clock.restart();
        music.getStatus();
        sf::Time c = clock.restart();

        std::cout << "openFromFile: " << a.asMicroseconds() << "\n";
        std::cout << "play:         " << b.asMicroseconds() << "\n";
        std::cout << "getStatus:    " << c.asMicroseconds() << "\n";

        int x = 0;
        std::cin>>x;

        return(0);
}

Results in:

openFromFile: 2
play:         700
getStatus:    27865

Removing the couts fixes it though... Why would pending couts cause such a large delay only in getStatus?

[binary1248]

I'm guessing this is because of unlucky lock contention scenarios. If you manage to call getStatus() right in the block where the thread is allocating the OpenAL buffer, it might block for a "long" time, long being the time it takes for the OpenAL buffer to get allocated and the sound to start playing. Since this depends on that and a lot of other timings, it is understandable that it won't be reproducible by everyone, especially because it is related to the overall performance of the system as well.

Since I could reproduce this, I went ahead and made a micro-patch to try and resolve it. You can try it out here: https://github.com/SFML/SFML/tree/bugfix/soundstream_contention

[Acumen]

Awesome! Works beautifully. Thank you very much!

I really need to brush up on my threading, its been a while.  I would love to be more useful. While digging around the source I passed right by there without a second thought.