OSSForks/node
1
0
Fork 0
mirror of https://github.com/zebrajr/node.git synced 2026-01-15 12:15:26 +00:00
Code Issues Actions 8 Packages Projects Releases Wiki Activity

test: make test-worker-prof more robust

Browse Source 
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 <benjamingr@gmail.com>
This commit is contained in:
Joyee Cheung
2023-09-04 23:53:59 +02:00
committed by GitHub
parent 47c5152545
commit 7f001c2299
1 changed files with 61 additions and 57 deletions
Download Patch File Download Diff File Expand all files Collapse all files

118
test/sequential/test-worker-prof.js
View File

@@ -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)
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(`
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);
}
});
`, { eval: true });
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];
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 logfiles = fs.readdirSync(tmpdir.path).filter((name) => name.endsWith('.log'));
assert.deepStrictEqual(new Set(logfiles), new Set([workerProf, parentProf]));
// 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`);
}
const workerLines = fs.readFileSync(tmpdir.resolve(workerProf), 'utf8').split('\n');
const parentLines = fs.readFileSync(tmpdir.resolve(parentProf), 'utf8').split('\n');
const workerTicks = workerLines.filter((line) => line.startsWith('tick'));
const parentTicks = parentLines.filter((line) => line.startsWith('tick'));
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')}`);
}