ASYNCIFY=1 emscripten_sleep broken

[benjamin-sieffert]

It seems that emscripten_sleep with ASYNCIFY=1, when called with low amount of ms (e.g. 16 or 1) often sleeps for 1000 ms or 0 ms instead of the requested amount.
See further down for bisection.

Reproducer: https://github.com/benjamin-sieffert/emscripten-sleep-bug
All details for how to run are in the repo.
Sorry the reproducer being in Rust – it does work with older versions of emscripten (see below), so this must be related to emscripten somehow.

[brendandahl]

I was unable to reproduce with the following:

#include <stdio.h>
#include <emscripten.h>

int main() {

  for (int i = 0; i < 100; i++) {
    EM_ASM(
      globalThis.start = performance.now();
    );
    emscripten_sleep(16);
    EM_ASM(
      console.log(performance.now() - start);
    );
  }

}

emcc -sASYNCIFY=1 -g main.c -o a.out.html

Could you try bisecting?

[benjamin-sieffert]

Is indeed hard to reproduce in C.
The best I can do is run code in an inactive tab, which at least results in 1000 ms sleeps. But no early wakeups.
So I figure the 1000ms come from the browser suspending for a long time if the code is not 'active' for the user.
Meanwhile I removed all SDL code from my reproducer and still had the same issue. So it seems to be a Rust/emscripten integration issue after all.

Now the questions are maybe:

• Why might the Rust code be treated as inactive by the browser?
• Why does it so often wake up early, though?
• Why was it not the case on emscripten from May last year?

I will try filing a bug in the Rust repo, too, but maybe you have an idea what could be wrong from a WASM perspective?
It might be related to stack layout etc.
It might also be a compiler optimization, but turning them all off and black-boxing the call to sleep does not help.

[brendandahl]

setTimeout is throttled to 1000ms on background tabs. Are you seeing a 1000ms pause on foreground tabs too?

[benjamin-sieffert]

Could you try bisecting?

I bisected manually by jumping commits in this repo. The culprit is c8857a6.
The PR says it’s only reverting a change made in #16966 , so I went back to commit 3f9d6b9 (just before #16966) and that commit is actually 🆗 for me.
So it seems that maybe the long vs int change is not even the problem, but in the reversion of the change there was some inconsistency or oversight that breaks things in my case.

All testing was done with:
clang 15
binaryen 109
nodejs v16.17.1
rustc 1.71.0

edit: Switched to rustc 1.73.0-nightly (ad963232d 2023-07-14) with -Z build-std to make sure it’s not an issue of compiled libc mismatch. I doubt it actually compiles the whole chain in the intended fashion, but at least I do get somewhat different behaviour, probably just related to using nightly over stable:
cc1112a is the first broken commit in this case

Seems all maybe a bit dubious. Will try getting into the emsdk install [HASH] way of bisecting.

edit: Using the full emsdk bisection approach with rustc 1.73.0-nightly (39f42ad9e 2023-07-19) and -Z build-std found emscripten-releases commit 174e35372a4e3c3c2cf95742a92e4d20f5f6f22d

    2022-07-08 sbc@chromium.org Move runtime_legacy.js to library_legacy.js (#17390)
    2022-07-08 sbc@chromium.org Fix typo from github-suggested patch to #17388
    2022-07-08 sbc@chromium.org Use automatic dependency detection for runtimeKeepalivePush/Pop. NFC (#17395)
    2022-07-08 sbc@chromium.org Remove needless internal use of Module object. NFC (#17388)
    2022-07-08 sbc@chromium.org Optimize convertJsFunctionToWasm to avoid garbage. NFC (#17402)
    2022-07-08 sbc@chromium.org Use 64 bits for time_t (#17401)

So this is again pointing to #17401.

---

Are you seeing a 1000ms pause on foreground tabs too?

Yes, but what is more, when trying to sleep 16 ms and intentionally spinning until I actually reach that amount of sleep (expecting potential early wakeups), I see this:

• 50 early wake ups where sleep time was mostly less than 0 ms (maybe immediate wakeup)
• then suddenly one sleep for 1000 ms

[benjamin-sieffert]

OK, I think this hinted in the right direction. When I use emscripten_get_now instead of Instant::now() for timekeeping, I do not get the "sleep bug" – so it is not a sleep bug after all, but an issue of how the Rust-std Instant::now for emscripten has internally corrupted timestamps, because c8857a6 was not picked up properly.

Yep, seems that time_t is wrong in the libc wrapper https://github.com/rust-lang/libc/blob/af676d102b238ea605cb7bdbe61ffac7903b7c51/src/unix/linux_like/emscripten/mod.rs#L23-L33

Filed rust-lang/libc#3306 – it’s curious that the issue did not exist before #16966 even though the definition for emscripten’s time_t in the libc wrapper is 6 years old.

[benjamin-sieffert]

May it not be that long is 32-bit on wasm32, yet _Int64 is 64-bit?
Referring to the comment of @sbc100 in #16966 …

This doesn't change the size of the type for wasm32

[benjamin-sieffert]

Fixing this in rust-lang/libc#3307.
The only wrong/misleading thing was the description of #17401

The change to 32-bit was only recently made in #16966.

– on wasm32, time_t had always been 32 bit. It’s 64 bit now and that’s alright, just needs to be reflected in the Rust-side shim.