test: make test-worker-prof more robust

test/sequential/test-worker-prof.js

@@ -3,77 +3,81 @@ const common = require('../common');
 const tmpdir = require('../common/tmpdir');
 const fs = require('fs');
 const assert = require('assert');
-const util = require('util');
-const { spawnSync } = require('child_process');
+const { spawnSyncAndExitWithoutError } = require('../common/child_process');
 
 // Test that --prof also tracks Worker threads.
 // Refs: https://github.com/nodejs/node/issues/24016
 
 if (process.argv[2] === 'child') {
-  const fs = require('fs');
-  let files = fs.readdirSync(tmpdir.path);
-  const plog = files.filter((name) => /\.log$/.test(name))[0];
-  if (plog === undefined) {
-    console.error('`--prof` did not produce a profile log for parent thread!');
-    process.exit(1);
-  }
-  const pingpong = `
-  let counter = 0;
-  const fs = require('fs');
-  const { Worker, parentPort  } = require('worker_threads');
-  parentPort.on('message', (m) => {
-    if (counter++ === 1024)
+  let files = fs.readdirSync(process.cwd());
+  console.log('files found in working directory before worker starts', files);
+  const parentProf = files.find((name) => name.endsWith('.log'));
+  assert(parentProf, '--prof did not produce a profile log for parent thread');
+  console.log('parent prof file:', parentProf);
+
+  const { Worker } = require('worker_threads');
+  const w = new Worker(`
+  const { parentPort, workerData } = require('worker_threads');
+
+  const SPIN_MS = 1000;
+  const start = Date.now();
+  parentPort.on('message', (data) => {
+    if (Date.now() - start < SPIN_MS) {
+      parentPort.postMessage(data);
+    } else {
       process.exit(0);
-    parentPort.postMessage(
-      fs.readFileSync(m.toString()).slice(0, 1024 * 1024));
+    }
   });
-  `;
+`, { eval: true });
 
-  const { Worker } = require('worker_threads');
-  const w = new Worker(pingpong, { eval: true });
-  w.on('message', (m) => {
-    w.postMessage(__filename);
+  let count = 1;
+  w.postMessage('hello\n');
+  w.on('message', () => {
+    count++;
+    w.postMessage('hello\n');
   });
 
   w.on('exit', common.mustCall(() => {
-    files = fs.readdirSync(tmpdir.path);
-    const wlog = files.filter((name) => /\.log$/.test(name) && name !== plog)[0];
-    if (wlog === undefined) {
-      console.error('`--prof` did not produce a profile log' +
-                    ' for worker thread!');
-      process.exit(1);
-    }
-    process.exit(0);
+    console.log(`parent posted ${count} messages`);
+    files = fs.readdirSync(process.cwd());
+    console.log('files found in working directory before worker exits', files);
+    const workerProf = files.find((name) => name !== parentProf && name.endsWith('.log'));
+    assert(workerProf, '--prof did not produce a profile log for worker thread');
+    console.log('worker prof file:', workerProf);
   }));
-  w.postMessage(__filename);
 } else {
   tmpdir.refresh();
-  const timeout = common.platformTimeout(30_000);
-  const spawnResult = spawnSync(
+
+  const workerProfRegexp = /worker prof file: (.+\.log)/;
+  const parentProfRegexp = /parent prof file: (.+\.log)/;
+  const { stdout } = spawnSyncAndExitWithoutError(
     process.execPath, ['--prof', __filename, 'child'],
-    { cwd: tmpdir.path, encoding: 'utf8', timeout });
-  assert.strictEqual(spawnResult.stderr.toString(), '',
-                     `child exited with an error: \
-                     ${util.inspect(spawnResult)}`);
-  assert.strictEqual(spawnResult.signal, null,
-                     `child exited with signal: ${util.inspect(spawnResult)}`);
-  assert.strictEqual(spawnResult.status, 0,
-                     `child exited with non-zero status: \
-                     ${util.inspect(spawnResult)}`);
-  const files = fs.readdirSync(tmpdir.path);
-  const logfiles = files.filter((name) => /\.log$/.test(name));
-  assert.strictEqual(logfiles.length, 2);  // Parent thread + child thread.
+    { cwd: tmpdir.path, encoding: 'utf8' }, {
+      stdout(output) {
+        console.log(output);
+        assert.match(output, workerProfRegexp);
+        assert.match(output, parentProfRegexp);
+        return true;
+      }
+    });
+  const workerProf = stdout.match(workerProfRegexp)[1];
+  const parentProf = stdout.match(parentProfRegexp)[1];
+
+  const logfiles = fs.readdirSync(tmpdir.path).filter((name) => name.endsWith('.log'));
+  assert.deepStrictEqual(new Set(logfiles), new Set([workerProf, parentProf]));
+
+  const workerLines = fs.readFileSync(tmpdir.resolve(workerProf), 'utf8').split('\n');
+  const parentLines = fs.readFileSync(tmpdir.resolve(parentProf), 'utf8').split('\n');
 
-  for (const logfile of logfiles) {
-    const lines = fs.readFileSync(
-      tmpdir.resolve(logfile), 'utf8').split('\n');
-    const ticks = lines.filter((line) => /^tick,/.test(line)).length;
+  const workerTicks = workerLines.filter((line) => line.startsWith('tick'));
+  const parentTicks = parentLines.filter((line) => line.startsWith('tick'));
 
-    // Test that at least 15 ticks have been recorded for both parent and child
-    // threads. When not tracking Worker threads, only 1 or 2 ticks would
-    // have been recorded.
-    // When running locally, this number is usually around 200
-    // for both threads, so 15 seems like a very safe threshold.
-    assert(ticks >= 15, `${ticks} >= 15`);
-  }
+  console.log('worker ticks', workerTicks.length);
+  console.log('parent ticks', parentTicks.length);
+  // When not tracking Worker threads, only 1 or 2 ticks would
+  // have been recorded.
+  // prof_sampling_interval is by default 1 millsecond. A higher NODE_TEST_SPIN_MS
+  // should result in more ticks, while 15 should be safe on most machines.
+  assert(workerTicks.length > 15, `worker ticks <= 15:\n${workerTicks.join('\n')}`);
+  assert(parentTicks.length > 15, `parent ticks <= 15:\n${parentTicks.join('\n')}`);
 }