Performance Issues and NOS3 Time Driver Slowdown

[kevincbruce]

While taking performance metrics, we found that there is extreme slowdown in time driver (between 0.66 and 0.75 speed with one satellite, down to ~0.22 with 8 satellites, around ~0.33 with 4 satellites), and it is still not eating up as many resources as it could (stays at using less than one additional core and around 1-2GB additional RAM per extra craft). This likely means that something is slowing down time driver, as it waits for all apps to post before it ticks. With 1 satellite, it will drive at 0.92-1.02 speed if you attempt to run a 2x. Will gain metrics for running at 4 satellites and see if increasing speed would bring it to parity, but we should resolve it so that at 1x speed it will take what resources it needs to run as close to 1x as possible.

[kevincbruce]

Further notes:

• 42 GUI is a big resource consumption factor. Turning it off will decrease consumption greatly, and brings it from having trouble running 2 or 4 satellites with 8 cores, 32GB of RAM, to being able to run 8 satellites with resources to spare.
• 42 GUI is not the source of Time Driver Slowdown, as the speeds above are reported with 42GUI disabled on all spacecraft, though the time driver is linked properly to all spacecraft and 42 is still running under the hood.
• After testing with 4 satellites, with the same configuration as in the tests above (full config, but with the 42 GUI disabled), it seems speedup is limited to around 0.5 at 4 satellites, with it approaching it at 8x, then pegging at it without going beyond consistently at 16x and 32.05x speed. At that point, it is utilizing all 8 cores at around 60-70%, but only using around 2.82 GB of RAM.
• It seems at 8x, it is not quite locked to 0.5 speed, fluctuating between 0.47 and 0.51 speed, while at higher speeds it is locked to 0.5 with no deviation. RAM Utilization also stays consistent, dropping to 2.81GB from 2.82GB at 16x and 8x, and core utilization drops to all 4 at around 57-67% (seeming to average at around 60% at 0.8, while it averages closer to 65 or 70% at 32x)

[kevincbruce]

Also when speeding up to 32x, it went to 32.05x instead, and then when slowing back down, it was at 16.03x and 8.01x instead of 16x and 8x like the first time through.

[sdunlap-afit]

I also noticed this issue and did a bit of digging. Looking at time_driver.cpp, I believe at least part of the issue is related to the main loop in TimeDriver::run().

while(1){
     std::this_thread::sleep_for(std::chrono::microseconds(_real_microseconds_per_tick));

    [Do stuff]
}

This method doesn't take into account the amount of time [Do stuff] takes to execute. With a default sleep of 10ms, this could account for a significant percentage difference that only gets worse as you speed up the simulation (smaller _real_microseconds_per_tick values).

On the latest main branch with default config, I get an actual speed-up of 0.8.

attempted speed-up =  1.00
actual speed-up =  0.79

It would be better to measure how long [Do stuff] takes and sleep for _real_microseconds_per_tick - (now - last_time). This still wouldn't consider the overhead for the sleep call (or thread switching), but you could also wait in a loop to avoid the sleep call altogether. Even with this method, though, my system caps out at 4x speed, so there's something else at play. I made some other modifications to test this method, but here's a snippet. With this method, I get exact actual speed-up values below 4x speed.

while(1){
    do{
        gettimeofday(&_now, NULL);
     } while (time_diff() < _real_microseconds_per_tick);
     
     // Added variable for updating the display
     _last_time_diff = time_diff();  // Modified time_diff() to return us
     _then = _now;
}

[jlucas9]

Merged into dev! Will continue to look for performance improvements and happy to accept recommendations!