Instant::now() broken on emscripten target

[benjamin-sieffert]

When targeting wasm32-unknown-emscripten with emscripten versions after probably emscripten-core/emscripten@c8857a6 and ASYNCIFY=1, all async operations are extremely broken, often waking up after 0 ms or 1000 ms. This is most easily observed with emscripten_sleep calls, but when I was running a multithreaded program with

• RUSTFLAGS='-C target-feature=+atomics,+bulk-memory,+mutable-globals'
• and linker flags (emcc) -pthread -s PTHREAD_POOL_SIZE=4 -s PTHREAD_POOL_SIZE_STRICT=2 ASYNCIFY=1
• and cargo build -Z build-std=std,panic_abort --target wasm32-unknown-emscripten

the same issue could also be observed when using std::sync::mpsc::Receiver::try_recv, for example.
The call would take 1000 ms instead of returning immediately.

Note that emscripten-core/emscripten@c8857a6 mentions that it is only (mostly) reverting emscripten-core/emscripten#16966 , BUT I do not observe the issue before 16966 nor during the time that 16966 is active.

Reproducer: https://github.com/benjamin-sieffert/emscripten-sleep-bug
All the SDL interaction can be removed and the problem still persists.

Filed an issue with emscripten at first, but it seems that the problem cannot be reproduced in C.
So it must lie in the Rust-emscripten interaction somehow, even though I am only directly calling extern "C" emscripten_sleep from Rust.
emscripten-core/emscripten#19872

[Jules-Bertholet]

@rustbot label O-wasm

[benjamin-sieffert]

Bisected the issue in emscripten down to commit emscripten-core/emscripten@c8857a6.
I think this change was probably not completely picked up by the rust emscripten stdlib and there is now a corruption of Instant::now() because the wrong integer size is expected.
I can fix the "sleep issue" by using emscripten_get_now over Instant::now to find the required sleep time.
The problem in try_recv probably comes down to internal usage of Instant::now, or else I was using recv_timeout and am mixing them up in memory.

To summarize the phenomenon: Instant::now() has no subsecond resolution on emscripten target.
.elapsed().as_millis() will return 0 until a whole second has passed, then it returns 1000. etc.

Reproducer:

use std::time::Instant;

#[cfg(target_os = "emscripten")]
mod emscripten {
    use std::os::raw::c_uint;

    extern "C" {
        pub fn emscripten_get_now() -> f64;
        pub fn emscripten_sleep(ms: c_uint);
    }

    pub fn now() -> f64 {
        unsafe { emscripten_get_now() }
    }

    pub fn sleep(ms: u32) {
        unsafe {
            emscripten_sleep(ms);
        }
    }
}

#[cfg(target_os = "emscripten")]
fn main() {
    // last emscripten_now point in time that Instant::now has ACK’d of passing
    let mut last_acknowledged = emscripten::now();

    let mut denied = 0;

    loop {
        let now = Instant::now();
        let enow = emscripten::now();

        emscripten::sleep(16);

        let elapsed = now.elapsed().as_millis();

        // some time has passed according to `Instant`
        if elapsed > 0 {
            let ack_now = emscripten::now();

            // time spent during sleep(16) according to emscripten
            let elapsed_emscripten = ack_now - enow;

            // time spent since last ack passage of time according to emscripten
            let elapsed_complete = ack_now - last_acknowledged;

            println!(
                "Instant acknowledges that {} ms have passed, after {} denied passings of time.
The real sleep duration this time according to emscripten was {} ms.
Time passed since previous non-denied passage according to emscripten: {}",
                elapsed, denied, elapsed_emscripten, elapsed_complete
            );

            last_acknowledged = ack_now;
            denied = 0;
        } else {
            // Instant claims that no time has passed
            denied += 1;
        }
    }
}

Prints:

(index):113 Instant acknowledges that 1000 ms have passed, after 52 denied passings of time.
(index):113 The real sleep duration this time according to emscripten was 17.399999976158142 ms.
(index):113 Time passed since previous non-denied passage according to emscripten: 1000

(index):113 Instant acknowledges that 1000 ms have passed, after 52 denied passings of time.
(index):113 The real sleep duration this time according to emscripten was 17.399999976158142 ms.
(index):113 Time passed since previous non-denied passage according to emscripten: 999.8999999761581

(index):113 Instant acknowledges that 1000 ms have passed, after 52 denied passings of time.
(index):113 The real sleep duration this time according to emscripten was 16.69999998807907 ms.
(index):113 Time passed since previous non-denied passage according to emscripten: 999.4000000357628

etc.

[benjamin-sieffert]

Continues in rust-lang/libc#3306