diff --git a/test/sequential/test-perf-hooks.js b/test/sequential/test-perf-hooks.js index d0ee0f5aad04c8..5ed9ff22ce2d38 100644 --- a/test/sequential/test-perf-hooks.js +++ b/test/sequential/test-perf-hooks.js @@ -1,84 +1,165 @@ 'use strict'; const common = require('../common'); -const assert = require('assert'); const { performance } = require('perf_hooks'); +// Get the start time as soon as possible. +const testStartTime = performance.now(); +const assert = require('assert'); +const { writeSync } = require('fs'); -if (!common.isMainThread) - common.skip('bootstrapping workers works differently'); +// Use writeSync to stdout to avoid disturbing the loop. +function log(str) { + writeSync(1, str + '\n'); +} assert(performance); assert(performance.nodeTiming); assert.strictEqual(typeof performance.timeOrigin, 'number'); + +assert(testStartTime > 0, `${testStartTime} <= 0`); // Use a fairly large epsilon value, since we can only guarantee that the node // process started up in 15 seconds. -assert(Math.abs(performance.timeOrigin - Date.now()) < 15000); +assert(testStartTime < 15000, `${testStartTime} >= 15000`); -const inited = performance.now(); -assert(inited < 15000); +// Use different ways to calculate process uptime to check that +// performance.timeOrigin and performance.now() are in reasonable range. +const epsilon = 50; +{ + const uptime1 = Date.now() - performance.timeOrigin; + const uptime2 = performance.now(); + const uptime3 = process.uptime() * 1000; + assert(Math.abs(uptime1 - uptime2) < epsilon, + `Date.now() - performance.timeOrigin (${uptime1}) - ` + + `performance.now() (${uptime2}) = ` + + `${uptime1 - uptime2} >= +- ${epsilon}`); + assert(Math.abs(uptime1 - uptime3) < epsilon, + `Date.now() - performance.timeOrigin (${uptime1}) - ` + + `process.uptime() * 1000 (${uptime3}) = ` + + `${uptime1 - uptime3} >= +- ${epsilon}`); +} assert.strictEqual(performance.nodeTiming.name, 'node'); assert.strictEqual(performance.nodeTiming.entryType, 'node'); -const delay = 250; -function checkNodeTiming(props) { - console.log(props); - - for (const prop of Object.keys(props)) { - if (props[prop].around !== undefined) { - assert.strictEqual(typeof performance.nodeTiming[prop], 'number'); - const delta = performance.nodeTiming[prop] - props[prop].around; - assert( - Math.abs(delta) < (props[prop].delay || delay), - `${prop}: ${Math.abs(delta)} >= ${props[prop].delay || delay}` - ); - } else { - assert.strictEqual(performance.nodeTiming[prop], props[prop], - `mismatch for performance property ${prop}: ` + - `${performance.nodeTiming[prop]} vs ${props[prop]}`); - } - } +// Copy all the values from the getters. +const initialTiming = { ...performance.nodeTiming }; + +{ + const { + startTime, + nodeStart, + v8Start, + environment, + bootstrapComplete, + } = initialTiming; + + assert.strictEqual(startTime, 0); + assert.strictEqual(typeof nodeStart, 'number'); + assert(nodeStart > 0, `nodeStart ${nodeStart} <= 0`); + // The whole process starts before this test starts. + assert(nodeStart < testStartTime, + `nodeStart ${nodeStart} >= ${testStartTime}`); + + assert.strictEqual(typeof v8Start, 'number'); + assert(v8Start > 0, `v8Start ${v8Start} <= 0`); + // V8 starts after the process starts. + assert(v8Start > nodeStart, `v8Start ${v8Start} <= ${nodeStart}`); + // V8 starts before this test starts. + assert(v8Start < testStartTime, + `v8Start ${v8Start} >= ${testStartTime}`); + + assert.strictEqual(typeof environment, 'number'); + assert(environment > 0, `environment ${environment} <= 0`); + // Environment starts after V8 starts. + assert(environment > v8Start, + `environment ${environment} <= ${v8Start}`); + // Environment starts before this test starts. + assert(environment < testStartTime, + `environment ${environment} >= ${testStartTime}`); + + assert.strictEqual(typeof bootstrapComplete, 'number'); + assert(bootstrapComplete > 0, `bootstrapComplete ${bootstrapComplete} <= 0`); + // Bootstrap completes after environment starts. + assert(bootstrapComplete > environment, + `bootstrapComplete ${bootstrapComplete} <= ${environment}`); + // Bootstrap completes before this test starts. + assert(bootstrapComplete < testStartTime, + `bootstrapComplete ${bootstrapComplete} >= ${testStartTime}`); } -checkNodeTiming({ - name: 'node', - entryType: 'node', - startTime: 0, - duration: { around: performance.now() }, - nodeStart: { around: 0 }, - v8Start: { around: 0 }, - bootstrapComplete: { around: inited, delay: 2500 }, - environment: { around: 0 }, - loopStart: -1, - loopExit: -1 -}); +function checkNodeTiming(timing) { + // Calculate the difference between now() and duration as soon as possible. + const now = performance.now(); + const delta = Math.abs(now - timing.duration); + + log(JSON.stringify(timing, null, 2)); + // Check that the properties are still reasonable. + assert.strictEqual(timing.name, 'node'); + assert.strictEqual(timing.entryType, 'node'); + + // Check that duration is positive and practically the same as + // performance.now() i.e. measures Node.js instance up time. + assert.strictEqual(typeof timing.duration, 'number'); + assert(timing.duration > 0, `timing.duration ${timing.duration} <= 0`); + assert(delta < 10, + `now (${now}) - timing.duration (${timing.duration}) = ${delta} >= 10`); + + // Check that the following fields do not change. + assert.strictEqual(timing.startTime, initialTiming.startTime); + assert.strictEqual(timing.nodeStart, initialTiming.nodeStart); + assert.strictEqual(timing.v8Start, initialTiming.v8Start); + assert.strictEqual(timing.environment, initialTiming.environment); + assert.strictEqual(timing.bootstrapComplete, initialTiming.bootstrapComplete); + + assert.strictEqual(typeof timing.loopStart, 'number'); + assert.strictEqual(typeof timing.loopExit, 'number'); +} + +log('check initial nodeTiming'); +checkNodeTiming(initialTiming); +assert.strictEqual(initialTiming.loopExit, -1); -setTimeout(() => { - checkNodeTiming({ - name: 'node', - entryType: 'node', - startTime: 0, - duration: { around: performance.now() }, - nodeStart: { around: 0 }, - v8Start: { around: 0 }, - bootstrapComplete: { around: inited, delay: 2500 }, - environment: { around: 0 }, - loopStart: { around: inited, delay: 2500 }, - loopExit: -1 - }); -}, 1000); +function checkValue(timing, name, min, max) { + const value = timing[name]; + assert(value > 0, `${name} ${value} <= 0`); + // Loop starts after bootstrap completes. + assert(value > min, + `${name} ${value} <= ${min}`); + assert(value < max, `${name} ${value} >= ${max}`); +} + +let loopStart = initialTiming.loopStart; +if (common.isMainThread) { + // In the main thread, the loop does not start until we start an operation + // that requires it, e.g. setTimeout(). + assert.strictEqual(initialTiming.loopStart, -1); + log('Start timer'); + setTimeout(() => { + log('Check nodeTiming in timer'); + const timing = { ...performance.nodeTiming }; + checkNodeTiming(timing); + // Loop should start after we fire the timeout, and before we call + // performance.now() here. + loopStart = timing.loopStart; + checkValue(timing, 'loopStart', initialTiming.duration, performance.now()); + }, 1000); +} else { + // In the worker, the loop always starts before the user code is evaluated, + // and after bootstrap completes. + checkValue(initialTiming, + 'loopStart', + initialTiming.bootstrapComplete, + testStartTime); +} process.on('exit', () => { - checkNodeTiming({ - name: 'node', - entryType: 'node', - startTime: 0, - duration: { around: performance.now() }, - nodeStart: { around: 0 }, - v8Start: { around: 0 }, - bootstrapComplete: { around: inited, delay: 2500 }, - environment: { around: 0 }, - loopStart: { around: inited, delay: 2500 }, - loopExit: { around: performance.now() } - }); + log('Check nodeTiming in process exit event'); + const timing = { ...performance.nodeTiming }; + checkNodeTiming(timing); + // Check that loopStart does not change. + assert.strictEqual(timing.loopStart, loopStart); + checkValue(timing, + 'loopExit', + loopStart, + performance.now()); });