8000 test: make test-perf-hooks more robust and work with workers · nodejs/node@9610008 · GitHub
[go: up one dir, main page]
Skip to content

Commit 9610008

Browse files
joyeecheungUlisesGascon
joyeecheung
authored and
UlisesGascon
committed
test: make test-perf-hooks more robust and work with workers
Previously the test makes several assumptions about the absolute values of the nodeTiming fields, which can make the test flaky on slow machines. This patch rewrites the test to check the relative values instead. It also updates the test to make it work with workers instead of directly skipping in workers. PR-URL: #49197 Refs: nodejs/reliability#638 Reviewed-By: Debadree Chatterjee <debadree333@gmail.com> Reviewed-By: Antoine du Hamel <duhamelantoine1995@gmail.com>
1 parent dc8fff9 commit 9610008

File tree

1 file changed

+143
-62
lines changed

1 file changed

+143
-62
lines changed

‎test/sequential/test-perf-hooks.js‎

Lines changed: 143 additions & 62 deletions
Original file line numberDiff line numberDiff line change
@@ -1,84 +1,165 @@
11
'use strict';
22

33
const common = require('../common');
4-
const assert = require('assert');
54
const { performance } = require('perf_hooks');
5+
// Get the start time as soon as possible.
6+
const testStartTime = performance.now();
7+
const assert = require('assert');
8+
const { writeSync } = require('fs');
69

7-
if (!common.isMainThread)
8-
common.skip('bootstrapping workers works differently');
10+
// Use writeSync to stdout to avoid disturbing the loop.
11+
function log(str) {
12+
writeSync(1, str + '\n');
13+
}
914

1015
assert(performance);
1116
assert(performance.nodeTiming);
1217
assert.strictEqual(typeof performance.timeOrigin, 'number');
18+
19+
assert(testStartTime > 0, `${testStartTime} <= 0`);
1320
// Use a fairly large epsilon value, since we can only guarantee that the node
1421
// process started up in 15 seconds.
15-
assert(Math.abs(performance.timeOrigin - Date.now()) < 15000);
22+
assert(testStartTime < 15000, `${testStartTime} >= 15000`);
1623

17-
const inited = performance.now();
18-
assert(inited < 15000);
24+
// Use different ways to calculate process uptime to check that
25+
// performance.timeOrigin and performance.now() are in reasonable range.
26+
const epsilon = 50;
27+
{
28+
const uptime1 = Date.now() - performance.timeOrigin;
29+
const uptime2 = performance.now();
30+
const uptime3 = process.uptime() * 1000;
31+
assert(Math.abs(uptime1 - uptime2) < epsilon,
32+
`Date.now() - performance.timeOrigin (${uptime1}) - ` +
33+
`performance.now() (${uptime2}) = ` +
34+
`${uptime1 - uptime2} >= +- ${epsilon}`);
35+
assert(Math.abs(uptime1 - uptime3) < epsilon,
36+
`Date.now() - performance.timeOrigin (${uptime1}) - ` +
37+
`process.uptime() * 1000 (${uptime3}) = ` +
38+
`${uptime1 - uptime3} >= +- ${epsilon}`);
39+
}
1940

2041
assert.strictEqual(performance.nodeTiming.name, 'node');
2142
assert.strictEqual(performance.nodeTiming.entryType, 'node');
2243

23-
const delay = 250;
24-
function checkNodeTiming(props) {
25-
console.log(props);
26-
27-
for (const prop of Object.keys(props)) {
28-
if (props[prop].around !== undefined) {
29-
assert.strictEqual(typeof performance.nodeTiming[prop], 'number');
30-
const delta = performance.nodeTiming[prop] - props[prop].around;
31-
assert(
32-
Math.abs(delta) < (props[prop].delay || delay),
33-
`${prop}: ${Math.abs(delta)} >= ${props[prop].delay || delay}`
34-
);
35-
} else {
36-
assert.strictEqual(performance.nodeTiming[prop], props[prop],
37-
`mismatch for performance property ${prop}: ` +
38-
`${performance.nodeTiming[prop]} vs ${props[prop]}`);
39-
}
40-
}
44+
// Copy all the values from the getters.
45+
const initialTiming = { ...performance.nodeTiming };
46+
47+
{
48+
const {
49+
startTime,
50+
nodeStart,
51+
v8Start,
52+
environment,
53+
bootstrapComplete,
54+
} = initialTiming;
55+
56+
assert.strictEqual(startTime, 0);
57+
assert.strictEqual(typeof nodeStart, 'number');
58+
assert(nodeStart > 0, `nodeStart ${nodeStart} <= 0`);
59+
// The whole process starts before this test starts.
60+
assert(nodeStart < testStartTime,
61+
`nodeStart ${nodeStart} >= ${testStartTime}`);
62+
63+
assert.strictEqual(typeof v8Start, 'number');
64+
assert(v8Start > 0, `v8Start ${v8Start} <= 0`);
65+
// V8 starts after the process starts.
66+
assert(v8Start > nodeStart, `v8Start ${v8Start} <= ${nodeStart}`);
67+
// V8 starts before this test starts.
68+
assert(v8Start < testStartTime,
69+
`v8Start ${v8Start} >= ${testStartTime}`);
70+
71+
assert.strictEqual(typeof environment, 'number');
72+
assert(environment > 0, `environment ${environment} <= 0`);
73+
// Environment starts after V8 starts.
74+
assert(environment > v8Start,
75+
`environment ${environment} <= ${v8Start}`);
76+
// Environment starts before this test starts.
77+
assert(environment < testStartTime,
78+
`environment ${environment} >= ${testStartTime}`);
79+
80+
assert.strictEqual(typeof bootstrapComplete, 'number');
81+
assert(bootstrapComplete > 0, `bootstrapComplete ${bootstrapComplete} <= 0`);
82+
// Bootstrap completes after environment starts.
83+
assert(bootstrapComplete > environment,
84+
`bootstrapComplete ${bootstrapComplete} <= ${environment}`);
85+
// Bootstrap completes before this test starts.
86+
assert(bootstrapComplete < testStartTime,
87+
`bootstrapComplete ${bootstrapComplete} >= ${testStartTime}`);
4188
}
4289

43-
checkNodeTiming({
44-
name: 'node',
45-
entryType: 'node',
46-
startTime: 0,
47-
duration: { around: performance.now() },
48-
nodeStart: { around: 0 },
49-
v8Start: { around: 0 },
50-
bootstrapComplete: { around: inited, delay: 2500 },
51-
environment: { around: 0 },
52-
loopStart: -1,
53-
loopExit: -1
54-
});
90+
function checkNodeTiming(timing) {
91+
// Calculate the difference between now() and duration as soon as possible.
92+
const now = performance.now();
93+
const delta = Math.abs(now - timing.duration);
94+
95+
log(JSON.stringify(timing, null, 2));
96+
// Check that the properties are still reasonable.
97+
assert.strictEqual(timing.name, 'node');
98+
assert.strictEqual(timing.entryType, 'node');
99+
100+
// Check that duration is positive and practically the same as
101+
// performance.now() i.e. measures Node.js instance up time.
102+
assert.strictEqual(typeof timing.duration, 'number');
103+
assert(timing.duration > 0, `timing.duration ${timing.duration} <= 0`);
104+
assert(delta < 10,
105+
`now (${now}) - timing.duration (${timing.duration}) = ${delta} >= 10`);
106+
107+
// Check that the following fields do not change.
108+
assert.strictEqual(timing.startTime, initialTiming.startTime);
109+
assert.strictEqual(timing.nodeStart, initialTiming.nodeStart);
110+
assert.strictEqual(timing.v8Start, initialTiming.v8Start);
111+
assert.strictEqual(timing.environment, initialTiming.environment);
112+
assert.strictEqual(timing.bootstrapComplete, initialTiming.bootstrapComplete);
113+
114+
assert.strictEqual(typeof timing.loopStart, 'number');
115+
assert.strictEqual(typeof timing.loopExit, 'number');
116+
}
117+
118+
log('check initial nodeTiming');
119+
checkNodeTiming(initialTiming);
120+
assert.strictEqual(initialTiming.loopExit, -1);
55121

56-
setTimeout(() => {
57-
checkNodeTiming({
58-
name: 'node',
59-
entryType: 'node',
60-
startTime: 0,
61-
duration: { around: performance.now() },
62-
nodeStart: { around: 0 },
63-
v8Start: { around: 0 },
64-
bootstrapComplete: { around: inited, delay: 2500 },
65-
environment: { around: 0 },
66-
loopStart: { around: inited, delay: 2500 },
67-
loopExit: -1
68-
});
69-
}, 1000);
122+
function checkValue(timing, name, min, max) {
123+
const value = timing[name];
124+
assert(value > 0, `${name} ${value} <= 0`);
125+
// Loop starts after bootstrap completes.
126+
assert(value > min,
127+
`${name} ${value} <= ${min}`);
128+
assert(value < max, `${name} ${value} >= ${max}`);
129+
}
130+
131+
let loopStart = initialTiming.loopStart;
132+
if (common.isMainThread) {
133+
// In the main thread, the loop does not start until we start an operation
134+
// that requires it, e.g. setTimeout().
135+
assert.strictEqual(initialTiming.loopStart, -1);
136+
log('Start timer');
137+
setTimeout(() => {
138+
log('Check nodeTiming in timer');
139+
const timing = { ...performance.nodeTiming };
140+
checkNodeTiming(timing);
141+
// Loop should start after we fire the timeout, and before we call
142+
// performance.now() here.
143+
loopStart = timing.loopStart;
144+
checkValue(timing, 'loopStart', initialTiming.duration, performance.now());
145+
}, 1000);
146+
} else {
147+
// In the worker, the loop always starts before the user code is evaluated,
148+
// and after bootstrap completes.
149+
checkValue(initialTiming,
150+
'loopStart',
151+
initialTiming.bootstrapComplete,
152+
testStartTime);
153+
}
70154

71155
process.on('exit', () => {
72-
checkNodeTiming({
73-
name: 'node',
74-
entryType: 'node',
75-
startTime: 0,
76-
duration: { around: performance.now() },
77-
nodeStart: { around: 0 },
78-
v8Start: { around: 0 },
79-
bootstrapComplete: { around: inited, delay: 2500 },
80-
environment: { around: 0 },
81-
loopStart: { around: inited, delay: 2500 },
82-
loopExit: { around: performance.now() }
83-
});
156+
log('Check nodeTiming in process exit event');
157+
const timing = { ...performance.nodeTiming };
158+
checkNodeTiming(timing);
159+
// Check that loopStart does not change.
160+
assert.strictEqual(timing.loopStart, loopStart);
161+
checkValue(timing,
162+
'loopExit',
163+
loopStart,
164+
performance.now());
84165 33B9
});

0 commit comments

Comments
 (0)
0