Strange high CPU behavior when running repeating set_timeout_async

[rchl]

Description

A recurring set_timeout_async call seems to trigger a weird CPU usage pattern where the CPU usage will spike to 20/30% and then slowly keep getting lower until eventually rising again. Rinse and repeat.

Spike and then slow lowering:

Another spike after a couple of minutes:

I've reproduced this on Ubuntu in VM. On my Mac, I can't really see it but then it has a lot more CPUs so the issue might just be harder to notice (since I think CPU usage includes all CPUs).

Steps to reproduce

1. Create a Packages/User/timeout.py plugin with this content:

import sublime


def plugin_loaded():
    run_timeout()


def run_timeout():
    sublime.set_timeout_async(run_timeout, 250)

2. Watch the CPU usage

Expected behavior

CPU usage should be stable over a longer time when doing nothing.

Actual behavior

CPU usage spikes up and then slowly lowers to spike up again.

Environment

• Build: 3211, 4076
• Operating system and version: Ubuntu 19 / 20
• [Linux] Desktop Environment and/or Window Manager: Gnome (I think, default in Ubuntu)

[rchl]

It's the CPU usage of plugin_host mostly BTW.

[rchl]

Using set_timeout instead of set_timeout_async doesn't reproduce:

[deathaxe]

At least python 3.8 seems to behave normally on Windows

[wbond]

A text log of the set_timeout_async being called and then executed might be enlightening. Is this with a clean install? Is is possible you've got other plugins blocking the async thread, resulting in stampedes of set_timeout_async calls?

I added extra code, a print() call, and on 4074 on macOS I get a plugin_host-3.8 CPU usages of 0.04% and Sublime Text usage of 0.6% after a few minutes, with no spikes.

The only way I could raise the CPU usage was to repeatedly save the .py file, creating many simultaneous loops. However, even then the CPU usage was 3.0% on Sublime Text due to all of the console text being printed and the constant scrolling. plugin_host-3.8 was running at 0.2%.

[rchl]

I couldn't see significant CPU usage on Mac either.

On Linux it's quite apparent though. And with no other packages installed (Remove package shows nothing).

Logging run_timeout shows it being called in regular intervals (haven't measured but seems about 250ms as expected).

[rchl]

Python 3.8 host also reproduces.

It might be a Linux-specific problem.

[wbond]

So far things are pointing in that direction. If no one else on the team get a chance to look at this I should have some time later this week.

[BenjaminSchaaf]

I'm able to replicate this on linux.

[BenjaminSchaaf]

We've got a fix for this in the pipeline. Turns out we had a bug in our use of sem_timedwait, used for scheduling the async timeouts, which caused the event loop to busy spin. Thanks for narrowing this issue down to set_timeout_async!

[FichteFoll]

Curious to see if this is the same as what I experienced in #2439 but never found the time to investigate. Now that I checked again, it does seem that the situation has improved with ST4.

[BenjaminSchaaf]

Fixed in 4075