Simulation is running slower that expected

[TonyWelte]

Describe the Bug

I've been tracking down an issue we are facing with our simulation running at 0.9 instead of 1.0 (even lower on some machines).

It is not an issue with CPU/GPU load. Webot is using barely 10% on a 16 threads machine. Running in fast mode the simulation is running at 5 to 6 times real time speed. It's only when running in real time mode that it can't keep up a stable 1.0 ratio.

I've tracked down the issue to this piece of code (in WbSimulationWorld.cpp):

    // computing the mean of an history of several elapsedTime
    // improves significantly the stability of the algorithm
    // in case of simulations where elapsedTime oscillates often
    // above and below basicTimeStep.
    // Moreover it improves the stability of simulations where
    // basicTimeStep contains significant decimals
    mElapsedTimeHistory.append(elapsed);
    if (mElapsedTimeHistory.size() > qMax(4.0, 128.0 / timeStep))  // history size found empirically
      mElapsedTimeHistory.pop_front();
    double mean = 0.0;
    foreach (const int &v, mElapsedTimeHistory)
      mean += v;
    mean /= mElapsedTimeHistory.size();

    // useful hack: uncomment to run Webots at 90% of the real-time
    //              (if the real-time mode is enabled, of course)
    // mean *= 0.90;

    if (mean > timeStep && mSleepRealTime > 0.0) {
      mSleepRealTime -= 0.03 * timeStep;
      if (mSleepRealTime < 0)
        mSleepRealTime = 0.0;
    } else if (mean < timeStep)
      mSleepRealTime += 0.03 * timeStep;

    mTimer->start(mSleepRealTime);

Commenting out the last part that updates the timer period cause the simulation to be mostly stable with a real time ratio of 1.0.

I plotted the values of each variables and it looks like the time period is oscillating +/- 2ms around the expected timeStep.

I don't really understand how the adaptation of mSleepRealTime is supposed to work. The mean (which might be longer that timeStep if the simulation is running slower) is compared to timeStep which is constant and not affected by any slow down).

Expected behavior

Without issues with CPU load the simulation should be stable with a real time ratio around 1.0

System

• Operating System: Linux Ubuntu 24.04

[CoolSpy3]

So, what it looks like it's doing is using mSleepRealTime to correct for the simulation running too fast, using the mean as a measure of what the "average" step time (including mSleepRealTime) is. That means that the last if reads something like:

If each step is, on average, running slower than timeStep, decrease the time that we wait between steps (mSleepRealTime) (if possible).
Otherwise, if each step is, on average, running slower than timeStep, increase the time we wait between steps mSleepRealTime.

The oscillations are then caused by the fact that the mean is acting as a buffer, delaying the time until changes by mSleepRealTime can be detected, causing the algorithm to get stuck in an oscillation.
The simulation starts out with mSleepRealTime = timeStep [1] Your code takes some time to run, so Webots decreases mSleepRealTime to run in real time. Because mean is an average, it takes some time for it to catch up to how long the current steps are taking. By the time mean has caught up, Webots has then over-corrected mSleepRealTime to be too long. Rinse and repeat, and the system oscillates.

When you remove the correction, mSleepTime is just timeStep, so each step takes exactly timeStep plus however long your controller + Webots takes to execute a step (which is probably very small on your machine). So it appears to run at a constant speed.

What might fix it is to calculate what the optimal mSleepRealTime would've been for each step and average that rather than averaging how long each step actually took with the correction. That way, the value being averaged at each step is no longer dependent on the value calculated in previous steps, which should prevent this kind of oscillation from occurring.

[CoolSpy3]

I just made an attempt at implementing what I suggested above in #6898. Can you try installing that build and seeing if it fixes the issue?

Personally, I still get some oscillations on my end, but my PC is far from an ideal test bench.

Side note: I also see a similar effect when commenting out the lines you mentioned above (with the simulation speed dropping to ~0.8x), so I'm guessing your system might perform better.

[TonyWelte]

each step takes exactly timeStep plus however long your controller + Webots takes to execute a step

is that how QTimer works ? I'm not familiar with them but I expected the timer to trigger at the specified period irrespective of the processing time of the callback.

I ran a quick test using this code:

#include <QCoreApplication>
#include <QDebug>
#include <QThread>
#include <QTimer>
#include <chrono>
#include <iostream>
#include <thread>

using namespace std::chrono_literals;

int main(int argc, char *argv[]) {
  QCoreApplication app(argc, argv);

  int timerIntervalMs = 1000;  // 1 second
  auto sleepTimeMs = 900ms;

  QTimer timer;
  timer.setInterval(timerIntervalMs);

  auto lastTime = std::chrono::system_clock::now();

  QObject::connect(&timer, &QTimer::timeout, [&]() {
    static int count = 0;
    auto now = std::chrono::system_clock::now();
    auto now_ms = std::chrono::time_point_cast<std::chrono::milliseconds>(now);
    auto epoch = now_ms.time_since_epoch();
    auto value = std::chrono::duration_cast<std::chrono::milliseconds>(epoch);

    auto delta = std::chrono::duration_cast<std::chrono::milliseconds>(now - lastTime).count();
    lastTime = now;

    std::cout << "Timer fired at: " << value.count() << " ms (Delta: " << delta << " ms, Count: " << ++count << ")"
              << std::endl;

    // Simulate work by sleeping
    std::this_thread::sleep_for(sleepTimeMs);
  });

  timer.start();
  std::cout << "Timer started with interval: " << timerIntervalMs << " ms" << std::endl;

  return app.exec();
}

It seems like the timer is running every 1s despite the 900ms sleep. Also if I increase the sleep beyond the timer period the callback is triggered at the period of the sleep.

So I think the period adaptation might be entirely unnecessary. If the processing time is smaller that timeStep it will run fine at that period and if it's longer then it will run as fast as possible.

PS: I also tested your branch. The oscillations are mostly gone but it still stays below 1.0 real time ratio

[CoolSpy3]

each step takes exactly timeStep plus however long your controller + Webots takes to execute a step

is that how QTimer works ? I'm not familiar with them but I expected the timer to trigger at the specified period irrespective of the processing time of the callback.

I'm actually not super familiar with QTimers either. That's just how the code appears to be structured. I suppose a more accurate statement would be that elapsed is equal to that sum. After running your example, it does appear that QTimer works as you describe. My bad.

That being said, testing your example reveals some interesting interplay between QTimer and connect. Connections using Qt::QueuedConnection do work that way because Qt queues the timer signal until the callback is ready to receive it. However, other connections (ex. Qt::DirectConnection [idk if there are any other relevant ones]) will silently fail, causing the callback to be triggered at double the period.

At least on my system [Windows], I had to manually apply Qt::QueuedConnection in your sample, but that's probably platform differences.

Interestingly, on my system, setting the timer (in Webots) to a constant rate and using Qt::QueuedConnection still drops the simulation speed to ~0.7-0.8x. I'm not sure what causes this, but it's likely something to do with Webots' simulation loop being more complex.

On a hunch, I retested the Webots change on my linux machine, and I do not see the same behavior. So, barring some more in-depth testing, it looks like it might be a Windows phenomena. If that turns out to be the case, one possible solution might be to only include the block on Windows (and maybe mac; we'd need to find someone with a machine we could test on). That being said, I'm a little wary on making such a change without understanding what the underlying cause of the difference is.

[TonyWelte]

Interesting that this is OS specific. Have you tried setting the timer type to Qt::PreciseTimer ?

---

and maybe mac; we'd need to find someone with a machine we could test on

I have an old Intel mac, I'll dig it up and test that this weekend. How did you test on your machine ? Any world with a low basicTimeStep has the issue ?

---

That being said, I'm a little wary on making such a change without understanding what the underlying cause of the difference is.

Yes I agree with you. It concerns the main simulation loop so we definitely have to be careful making any change.

[CoolSpy3]

Interesting that this is OS specific. Have you tried setting the timer type to Qt::PreciseTimer ?

Great call! I just did a quick test, and it looks like that fixes it on Windows! (Webots now runs at ~1.0x) I guess the underlying OS API differences are the culprit. It's pretty late, so I'm not going to test it in-depth tonight, but it's pretty promising! (Changes are pushed to the PR branch.)

I have an old Intel mac, I'll dig it up and test that this weekend. How did you test on your machine ? Any world with a low basicTimeStep has the issue ?

Sounds good!

I've just been testing with the camera.wbt sample because that's what I had open last. I was comparing behavior with/without the mTimer->start(mSleepRealTime); line (because that's the only one that affects the rest of the program). I also tested your sample with Qt::DirectConnection and Qt::QueuedConnection. On Windows, DirectConnection introduces additional latency. Notably, Qt::PreciseTimer fixes this too! (Note: I did have to break the callback out into a QObject to set the connection type.)

[CoolSpy3]

Alright, I got to do just a bit of testing on Windows. It looks pretty stable overall. It looked like fast mode may've been running a little slower under this change, but I ran into another problem before I could test that properly, so it may've just been uneven load on my machine (see note). If that does end up being a problem, we can just swap back to CourseTimer when running in fast mode.

Note: I wanted to test the compiled build to remove any differences caused by my local build being in debug mode. However, the latest build was crashing on my machine due to a missing function definition. I think this is caused by PreciseTimer requiring another dll that wasn't being packaged. I'm pretty sure I figured out which one it is, and I've added it to the package. However, I have to sign off for tonight, so I haven't gotten the chance to confirm. I'm going on vacation for a few days starting tomorrow, so I want to be well-rested. As a side-effect, I will be away from my Windows machine until I get back, so I'll be unable to continue testing until mid-late next week.

[CoolSpy3]

Hey, just wanted to let you know that I haven't forgotten about this! A bunch of stuff has been happening, and I haven't gotten a chance to do any more investigation, but I'm still keeping this in the back of my head. Hopefully I can give you an actual update at some point 🤞