cli: add --trace-atomics-wait flag

Adds a flag that helps with debugging deadlocks due to incorrectly
implemented `Atomics.wait()` calls.

Author: addaleax

benchmark/worker/atomics-wait.js

@@ -0,0 +1,14 @@
+'use strict';
+
+const common = require('../common.js');
+const bench = common.createBenchmark(main, {
+  n: [1e7]
+});
+
+function main({ n }) {
+  const i32arr = new Int32Array(new SharedArrayBuffer(4));
+  bench.start();
+  for (let i = 0; i < n; i++)
+    Atomics.wait(i32arr, 0, 1);  // Will return immediately.
+  bench.end(n);
+}

doc/api/cli.md

@@ -816,6 +816,25 @@ added: v12.0.0
 Set default [`tls.DEFAULT_MIN_VERSION`][] to 'TLSv1.3'. Use to disable support
 for TLSv1.2, which is not as secure as TLSv1.3.
 
+### `--trace-atomics-wait`
+<!-- YAML
+added: REPLACEME
+-->
+
+Print short summaries of calls to `Atomics.wait()` to stderr.
+The output could look like this:
+
+```text
+[Thread 0] Atomics.wait(0x55d134fe4290 + 0, 1, inf) started
+[Thread 0] Atomics.wait(0x55d134fe4290 + 0, 1, inf) did not wait because the values mismatched
+[Thread 0] Atomics.wait(0x55d134fe4290 + 0, 0, 10) started
+[Thread 0] Atomics.wait(0x55d134fe4290 + 0, 0, 10) timed out
+[Thread 0] Atomics.wait(0x55d134fe4290 + 4, 0, inf) started
+[Thread 1] Atomics.wait(0x55d134fe4290 + 4, -1, inf) started
+[Thread 0] Atomics.wait(0x55d134fe4290 + 4, 0, inf) was woken up by another thread
+[Thread 1] Atomics.wait(0x55d134fe4290 + 4, -1, inf) was woken up by another thread
+```
+
 ### `--trace-deprecation`
 <!-- YAML
 added: v0.8.0
@@ -1205,6 +1224,7 @@ Node.js options that are allowed are:
 * `--tls-min-v1.1`
 * `--tls-min-v1.2`
 * `--tls-min-v1.3`
+* `--trace-atomics-wait`
 * `--trace-deprecation`
 * `--trace-event-categories`
 * `--trace-event-file-pattern`

doc/node.1

@@ -363,6 +363,10 @@ but the option is supported for compatibility with older Node.js versions.
 Set default minVersion to 'TLSv1.3'. Use to disable support for TLSv1.2 in
 favour of TLSv1.3, which is more secure.
 .
+.It Fl -trace-atomics-wait
+Print short summaries of calls to
+.Sy Atomics.wait() .
+.
 .It Fl -trace-deprecation
 Print stack traces for deprecations.
 .

src/node.cc

@@ -229,11 +229,54 @@ int Environment::InitializeInspector(
 }
 #endif  // HAVE_INSPECTOR && NODE_USE_V8_PLATFORM
 
+#define ATOMIC_WAIT_EVENTS(V)                                               \
+  V(kStartWait,           "started")                                        \
+  V(kWokenUp,             "was woken up by another thread")                 \
+  V(kTimedOut,            "timed out")                                      \
+  V(kTerminatedExecution, "was stopped by terminated execution")            \
+  V(kAPIStopped,          "was stopped through the embedder API")           \
+  V(kNotEqual,            "did not wait because the values mismatched")     \
+
+static void AtomicsWaitCallback(Isolate::AtomicsWaitEvent event,
+                                Local<v8::SharedArrayBuffer> array_buffer,
+                                size_t offset_in_bytes, int64_t value,
+                                double timeout_in_ms,
+                                Isolate::AtomicsWaitWakeHandle* stop_handle,
+                                void* data) {
+  Environment* env = static_cast<Environment*>(data);
+
+  const char* message;
+  switch (event) {
+#define V(key, msg)                         \
+    case Isolate::AtomicsWaitEvent::key:    \
+      message = msg;                        \
+      break;
+    ATOMIC_WAIT_EVENTS(V)
+#undef V
+  }
+
+  fprintf(stderr,
+          "[Thread %" PRIu64 "] Atomics.wait(%p + %zx, %" PRId64 ", %.f) %s\n",
+          env->thread_id(),
+          array_buffer->GetBackingStore()->Data(),
+          offset_in_bytes,
+          value,
+          timeout_in_ms,
+          message);
+}
+
 void Environment::InitializeDiagnostics() {
   isolate_->GetHeapProfiler()->AddBuildEmbedderGraphCallback(
       Environment::BuildEmbedderGraph, this);
   if (options_->trace_uncaught)
     isolate_->SetCaptureStackTraceForUncaughtExceptions(true);
+  if (options_->trace_atomics_wait) {
+    isolate_->SetAtomicsWaitCallback(AtomicsWaitCallback, this);
+    AddCleanupHook([](void* data) {
+      Environment* env = static_cast<Environment*>(data);
+      env->isolate()->SetAtomicsWaitCallback(nullptr, nullptr);
+    }, this);
+  }
 
 #if defined HAVE_DTRACE || defined HAVE_ETW
   InitDTrace(this);

src/node_options.cc

@@ -435,6 +435,10 @@ EnvironmentOptionsParser::EnvironmentOptionsParser() {
             "throw an exception on deprecations",
             &EnvironmentOptions::throw_deprecation,
             kAllowedInEnvironment);
+  AddOption("--trace-atomics-wait",
+            "trace Atomics.wait() operations",
+            &EnvironmentOptions::trace_atomics_wait,
+            kAllowedInEnvironment);
   AddOption("--trace-deprecation",
             "show stack traces on deprecations",
             &EnvironmentOptions::trace_deprecation,

src/node_options.h

@@ -140,6 +140,7 @@ class EnvironmentOptions : public Options {
   std::string redirect_warnings;
   bool test_udp_no_try_send = false;
   bool throw_deprecation = false;
+  bool trace_atomics_wait = false;
   bool trace_deprecation = false;
   bool trace_exit = false;
   bool trace_sync_io = false;

test/parallel/test-trace-atomics-wait.js

@@ -0,0 +1,74 @@
+'use strict';
+require('../common');
+const assert = require('assert');
+const child_process = require('child_process');
+const { Worker } = require('worker_threads');
+
+if (process.argv[2] === 'child') {
+  const i32arr = new Int32Array(new SharedArrayBuffer(8));
+  assert.strictEqual(Atomics.wait(i32arr, 0, 1), 'not-equal');
+  assert.strictEqual(Atomics.wait(i32arr, 0, 0, 10), 'timed-out');
+
+  new Worker(`
+  const i32arr = require('worker_threads').workerData;
+  Atomics.store(i32arr, 1, -1);
+  Atomics.notify(i32arr, 1);
+  Atomics.wait(i32arr, 1, -1);
+  `, { eval: true, workerData: i32arr });
+
+  Atomics.wait(i32arr, 1, 0);
+  assert.strictEqual(Atomics.load(i32arr, 1), -1);
+  Atomics.store(i32arr, 1, 0);
+  Atomics.notify(i32arr, 1);
+  return;
+}
+
+const proc = child_process.spawnSync(
+  process.execPath,
+  [ '--trace-atomics-wait', __filename, 'child' ],
+  { encoding: 'utf8', stdio: [ 'inherit', 'inherit', 'pipe' ] });
+
+if (proc.status !== 0) console.log(proc);
+assert.strictEqual(proc.status, 0);
+
+const expectedLines = [
+  { threadId: 0, offset: 0, value: 1, timeout: 'inf',
+    message: 'started' },
+  { threadId: 0, offset: 0, value: 1, timeout: 'inf',
+    message: 'did not wait because the values mismatched' },
+  { threadId: 0, offset: 0, value: 0, timeout: '10',
+    message: 'started' },
+  { threadId: 0, offset: 0, value: 0, timeout: '10',
+    message: 'timed out' },
+  { threadId: 0, offset: 4, value: 0, timeout: 'inf',
+    message: 'started' },
+  { threadId: 1, offset: 4, value: -1, timeout: 'inf',
+    message: 'started' },
+  { threadId: 0, offset: 4, value: 0, timeout: 'inf',
+    message: 'was woken up by another thread' },
+  { threadId: 1, offset: 4, value: -1, timeout: 'inf',
+    message: 'was woken up by another thread' }
+];
+
+let SABAddress;
+const re = /^\[Thread (?<threadId>\d+)\] Atomics\.wait\((?<SAB>(?:0x)?[0-9a-f]+) \+ (?<offset>\d+), (?<value>-?\d+), (?<timeout>inf|infinity|[0-9.]+)\) (?<message>.+)$/;
+for (const line of proc.stderr.split('\n').map((line) => line.trim())) {
+  if (!line) continue;
+  console.log('Matching', { line });
+  const actual = line.match(re).groups;
+  const expected = expectedLines.shift();
+
+  if (SABAddress === undefined)
+    SABAddress = actual.SAB;
+  else
+    assert.strictEqual(actual.SAB, SABAddress);
+
+  assert.strictEqual(+actual.threadId, expected.threadId);
+  assert.strictEqual(+actual.offset, expected.offset);
+  assert.strictEqual(+actual.value, expected.value);
+  assert.strictEqual(actual.message, expected.message);
+  if (expected.timeout === 'inf')
+    assert.match(actual.timeout, /inf(inity)?/);
+  else
+    assert.strictEqual(actual.timeout, expected.timeout);
+}