From d966328ee36a3d9b8970fd937d565965de785298 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Mon, 21 Aug 2023 18:17:17 +0200 Subject: [PATCH] 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/fixtures/workload/spin.js | 13 ++++ test/sequential/test-worker-prof.js | 100 ++++++++++++---------------- 2 files changed, 56 insertions(+), 57 deletions(-) create mode 100644 test/fixtures/workload/spin.js diff --git a/test/fixtures/workload/spin.js b/test/fixtures/workload/spin.js new file mode 100644 index 00000000000000..2222c890678396 --- /dev/null +++ b/test/fixtures/workload/spin.js @@ -0,0 +1,13 @@ +'use strict'; + +function shouldSpin(start, ms) { + return Date.now() - start < ms; +} + +function spin(ms) { + const start = Date.now(); + while (shouldSpin(start, ms)) {} +} + +const ms = parseInt(process.env.NODE_TEST_SPIN_MS, 10) || 1000; +spin(ms); diff --git a/test/sequential/test-worker-prof.js b/test/sequential/test-worker-prof.js index bcb5a477497d73..3be22379fc56e3 100644 --- a/test/sequential/test-worker-prof.js +++ b/test/sequential/test-worker-prof.js @@ -1,79 +1,65 @@ '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', 'spin.js'), { + env: { NODE_TEST_SPIN_MS: 100 } }); 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`); - } + 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, so spinning for 100 + // milliseconds should result in ~100 ticks. + assert(workerTicks.length > 15, `worker ticks <= 15:\n${workerTicks.join('\n')}`); + assert(parentTicks.length > 15, `parent ticks <= 15:\n${parentTicks.join('\n')}`); }