From c5d821d5fa71ae9126cdc0142d0005708695a0dc 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/sequential/test-worker-prof.js | 103 +++++++++++++--------------- 1 file changed, 46 insertions(+), 57 deletions(-) diff --git a/test/sequential/test-worker-prof.js b/test/sequential/test-worker-prof.js index bcb5a477497d73..ceb40c2e7e9031 100644 --- a/test/sequential/test-worker-prof.js +++ b/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`); }