From 359f7a0799a6c9f14bfbc0f4ac1f624347bd0512 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Mon, 4 Sep 2023 23:53:59 +0200 Subject: [PATCH] test: make test-worker-prof more robust Use a JS workload instead of repeating FS operations and use a timer to make it less flaky on machines with little resources. PR-URL: https://github.com/nodejs/node/pull/49274 Refs: https://github.com/nodejs/node/issues/26401 Refs: https://github.com/nodejs/reliability/issues/640 Reviewed-By: Benjamin Gruenbaum --- test/sequential/test-worker-prof.js | 116 ++++++++++++++-------------- 1 file changed, 60 insertions(+), 56 deletions(-) diff --git a/test/sequential/test-worker-prof.js b/test/sequential/test-worker-prof.js index bcb5a477497d73..cb6d580294b1cb 100644 --- a/test/sequential/test-worker-prof.js +++ b/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')}`); }