Regression in steady_clock skew between pthreads

[niklasf]

I am measuring std::chrono::steady_clock on the main thread and on a pthread, with a clear happens-before relationship. So the time difference should always be non-negative.

Starting in release 1.39.0 (both upstream and fastcomp), I see negative time differences down to around -100ms.

I bisected the issue and found a5117d7 (Fix pthreads with closure compiler (#9569)) as the first "bad" commit.

(While bisecting, I noticed previous versions also sometimes have negative time differences, but the worst I found was -9ms. I guess it's difficult to guarantee steady clock synchronization between WASM pthreads and I can easily find a workaround for my use case. Reporting this just in case something has been overlooked in a5117d7. If not, feel free to close.)

[kripken]

Thanks @niklasf !

Can you perhaps create a small testcase showing the issue? That would be much easier to debug, as reading the patch your bisection found, I'm not sure yet why it changed things.

[niklasf]

Unfortunately I can't reproduce the regression in a minimal example. So there's probably not much that can be done.

The qualitative issue, i.e. small negative time differences, is easy to reproduce:

---

Compiler flags:

em++ -s ASSERTIONS=1 -s TOTAL_MEMORY=20971520 -s NO_EXIT_RUNTIME=1 -s USE_PTHREADS=1 -s PTHREAD_POOL_SIZE=1 -s EXPORTED_FUNCTIONS="['_main', '_notify']" -s "EXTRA_EXPORTED_RUNTIME_METHODS=['ccall']" steady-clock.cc

Script:

<script src="a.out.js"></script>
<script>
Module.postRun = function() {
  setTimeout(function() {
    Module.ccall('notify', 'number', [], []);
  }, 1000);
};
</script>

C++:

#include <iostream>
#include <pthread.h>

typedef std::chrono::milliseconds::rep TimePoint;

TimePoint now() {
    return std::chrono::duration_cast<std::chrono::milliseconds>(
        std::chrono::steady_clock::now().time_since_epoch()).count();
}

static TimePoint ping;

static std::mutex mutex;
static std::condition_variable cond_var;
static bool done = false;

void *thread_main(void *arg) {
    std::cout << "running thread ..." << std::endl;

    std::unique_lock<std::mutex> lock(mutex);

    while (!done) {
        cond_var.wait(lock);
    }

    std::cout << "pong - ping: " << (now() - ping) << std::endl;
    return NULL;
}

extern "C" int notify() {
    std::unique_lock<std::mutex> lock(mutex);

    std::cout << "notifying ..." << std::endl;

    ping = now();
    done = true;

    cond_var.notify_one();

    return 0;
}

int main() {
    std::cout << "running main ..." << std::endl;

    pthread_attr_t attr;
    pthread_attr_init(&attr);

    pthread_t thread;
    pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED);
    int error = pthread_create(&thread, &attr, thread_main, NULL);
    if (error)
        abort();

    return 0;
}

Sample output:

running main ...
running thread ...
notifying ...
pong - ping: -4

[kripken]

Thanks for the testcase @niklasf !

Ok, I think I see what's going on here. That PR broke the __performance_now_clock_drift value, which before was a magic global, but after that PR we have no more such globals, and values must be passed around explicitly. Fix in #9799, please see if that helps your codebase.