Sponge: High CPU utilization by AsyncScheduler thread

[electron93]

I am currently running

• SpongeForge version: 1.12.2-2838-7.1.7-RC3947
• Java version: 1.8.0_222/64-bit
• Operating System: Linux
• Plugins/Mods: only one test plugin that schedules an empty task for every 5 seconds.

Issue Description

https://github.com/SpongePowered/SpongeCommon/commit/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa

@dualspiral

[dualspiral]

My original comment on Discord was:

Yes, at a quick glance, I think I see why. Without looking at your scheduler test, I bet that you have a recurring async task. That recurring async task doesn't finish before the next one starts.

In RC3946, the new task will start without waiting for the old one. In RC3947, this was committed - https://github.com/SpongePowered/SpongeCommon/commit/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa. What's going on now is that in recalibrateMinimumTimeout, the timeout is always zero because it wants to execute the task as soon as the old one finishes, but it does this by continuously checking because there is no pause between checks.

This will only happen with plugins that have tasks that take longer than their set period.

I can't fix this right now, but can you open an issue on SpongeCommon and tag me in it?

However, that wouldn't sit right with this statement that the task is empty, and runs every 5 seconds - if an empty task takes 5 seconds to execute then we have bigger problems.

It turns out there is a race condition here. The first part of it is this:

https://github.com/SpongePowered/SpongeCommon/blob/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa/src/main/java/org/spongepowered/common/scheduler/SchedulerBase.java#L174-L175

Once we start the task, we enter the RUNNING state. The key thing is what is going on in the startTask method, however:

https://github.com/SpongePowered/SpongeCommon/blob/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa/src/main/java/org/spongepowered/common/scheduler/SchedulerBase.java#L189-L190

The task gets set to EXECUTING before we run the task executor... but it's run within executeTaskRunnable as an anonymous method. This anonymous method, for the AsyncScheduler, is actually run within a thread pool - that is, on a different thread. In the ideal case here, task would to get set to the RUNNING state immediately after EXECUTING, which would be okay, but it would just mean that the previous issue the commit in question was meant to solve is still there.

It is possible, if not probable, however, for the thread setup time to be relatively large, meaning that control is passed back to the calling method well before the supplied executor is ready to be executed. As a result this would mean that the task would get set to the RUNNING state, THEN the EXECUTING state. The task would then be stuck in EXECUTING for all eternity, even after the task finished to run. This has two major side effects when the task is a repeating one:

• It will not run again; and
• The scheduler, as written, will continuously try to check to see if it can call the task, knowing that it is due to do so, but not doing so because it is in the EXECUTING phase.

As the EXECUTING phase is considered "active", the following can result in a zero minimum timeout:

https://github.com/SpongePowered/SpongeCommon/blob/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa/src/main/java/org/spongepowered/common/scheduler/AsyncScheduler.java#L90-L96

We then end up with a preTick that doesn't wait:

https://github.com/SpongePowered/SpongeCommon/blob/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa/src/main/java/org/spongepowered/common/scheduler/AsyncScheduler.java#L112

and then we move on to processing the executing task, which just returns and does nothing with it:

https://github.com/SpongePowered/SpongeCommon/blob/6b29fb92a97a512cb0c2cc00be3fe0cf6617edfa/src/main/java/org/spongepowered/common/scheduler/SchedulerBase.java#L153-L155

and then completes the loop, where the whole cycle of checking the minimum timeout, getting zero, and trying to execute again will continue to infinity.

I'll try to get around to fixing it tonight. It's a bit more complex than moving a check. I know what needs to be done, I just need a bit of time to fully test what's going on.

[dualspiral]

Fixed this in https://github.com/SpongePowered/SpongeCommon/commit/f7bde6a121d20b0f043b0d96ffd5edca711e103a - typo means I put the wrong issue in the commit!