test/sequential/test-perf-hooks.js

'use strict';

const common = require('../common');
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');

// 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(testStartTime < 15000, `${testStartTime} >= 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');

// If timing.duration gets copied into the argument instead of being computed
// via the getter, this should be called right after timing is created.
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');
// Copy all the values from the getters.
const initialTiming = { ...performance.nodeTiming };
checkNodeTiming(initialTiming);

{
  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}`);
}

assert.strictEqual(initialTiming.loopExit, -1);

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', () => {
  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());
});