test: make test-worker-prof more robust

Use a JS workload instead of repeating FS operations to make it
less flaky on machines with little resources.

test/sequential/test-worker-prof.js

@@ -1,79 +1,68 @@
 'use strict';
 const common = require('../common');
 const tmpdir = require('../common/tmpdir');
+const fixtures = require('../common/fixtures');
 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)
-      process.exit(0);
-    parentPort.postMessage(
-      fs.readFileSync(m.toString()).slice(0, 1024 * 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(pingpong, { eval: true });
-  w.on('message', (m) => {
-    w.postMessage(__filename);
+  const w = new Worker(fixtures.path('workload', 'fibonacci.js'), {
+    env: { FIB: 20, }
   });
 
   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);
+    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) {
+      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`);
-  }
+  // 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 100
+  // for both threads, so 15 seems like a very safe threshold.
+  // TODO(joyeecheung): if this still flakes, we could log the time spent on the
+  // workload in the worker and the parent, and divide that with v8's
+  // prof_sampling_interval to get a better expectation.
+  assert(workerTicks.length > 15, `worker ticks ${workerTicks} <= 15`);
+  assert(parentTicks.length > 15, `parent ticks ${parentTicks} <= 15`);
 }