Timing is Everything
This weekend I scratched a bit of a long term itch and implemented basic support for the Performance Timeline specification for Node.js core. Hopefully it will land soon.
There are still definitely some rough edges and certainly quite a few issues still to work out, but here’s how things work currently. Everything described below is subject to change.
require(‘perf_hooks’)
The new API is via require('perf_hooks').
const {
performance,
PerformanceObserver
} = require('perf_hooks');The performance property returns a Performance object that is roughly compliant to the High Resolution Time specification.
The purpose of the Performance object is to provide access to the “Performance Timeline”, a logical series of performance milestones and measures maintained both by the Node.js process and user code.
Internally, the timeline is nothing more than a linked list of PerformanceEntry objects. Each PerformanceEntry has a name, a type, a starting timestamp, and a duration. Multiple different PerformanceEntry types may exist in the Timeline at any given instant. The implementation currently supports four specific types: 'node' , 'frame' , 'mark' , 'measure' , 'gc' , and 'function'.These are all described below.
Node.js Performance Milestones
The first PerformanceEntry instance added to the Performance Timeline is a special entry that records the timestamps at which significant milestones occur in the startup of the Node.js process. There are a couple of ways of accessing this special entry but the fastest is to use perf_hooks.performance.nodeTime .
> perf_hooks.performance.nodeTiming
PerformanceNodeTiming {
duration: 4512.380027,
startTime: 158745518.63114,
entryType: 'node',
name: 'node',
arguments: 158745518.756349,
initialize: 158745519.09161,
inspectorStart: 158745522.408488,
loopStart: 158745613.442409,
loopExit: 0,
loopFrame: 158749857.025862,
bootstrapComplete: 158745613.439273,
third_party_main_start: 0,
third_party_main_end: 0,
cluster_setup_start: 0,
cluster_setup_end: 0,
module_load_start: 158745583.850295,
module_load_end: 158745583.851643,
preload_modules_load_start: 158745583.852331,
preload_modules_load_end: 158745583.879369 }The properties currently supported include:
duration: the number of milliseconds the process has been active.arguments: the timestamp at which command-line argument processing completed.initialize: the timestamp at which the Node.js platform completed initialization.inspectorStart: the timestamp at which the Node.js inspector startup completed.loopStart: the timestamp at which the Node.js event loop started.loopExit: the timestamp at which the Node.js event loop exited.loopFrame: the timestamp at which the current iteration of the Node.js event loop began.bootstrapComplete: the timestamp at which the Node.js bootstrap process completed.third_party_main_start: the timestamp at which third-party-main processing started.third_party_main_end: the timestamp at which third-party-main processing completed.cluster_setup_start: the timestamp at which cluster child setup started.cluster_setup_end: the timestamp at which cluster child setup ended.module_load_start: the timestamp at which the main module loading started.module_load_end: the timestamp at which the main module loading ended.preload_modules_load_start: the timestamp at which preload module loading started.preload_modules_load_end: the timestamp at which preload module loading ended.
Node.js Event Loop Timing
The second PerformanceEntry instance added to the timeline is a special entry used to track the timing of the Node.js event loop. This entry may be accessed using perf_hooks.performance.nodeFrame .
> perf_hooks.performance.nodeFrame
PerformanceFrame {
countPerSecond: 9.91151849696801,
count: 68,
prior: 0.124875,
entryType: 'frame',
name: 'frame',
duration: 128.827398,
startTime: 32623025.740256 }
>The properties supported include:
countsPerSecond: The number of event loop iterations per second.count: The total number of event loop iterationsstartTime: The timestamp at which the current iteration of the event loop began.duration: The current duration of the current iteration of the event loop.prior: The total number of milliseconds taken for the previous iteration of the event loop.
Marks and Measures
The implementation supports the User Timing API extension to the Performance Timeline. This allows users the ability to set named markers on the timeline and to measure the total number of milliseconds between those markers.
For example:
const {
performance,
PerformanceObserver
} = require('perf_hooks');performance.mark('A');
setImmediate(() => {
performance.mark('B');
performance.measure('A to C', 'A', 'B');
const measure = performance.getEntriesByName('A to C')[0];
console.log(measure.duration);
});
Measuring Function Execution Time
The implementation supports a mechanism for measuring the execution time of JavaScript functions.
const {
performance,
PerformanceObserver
} = require('perf_hooks');function myFunction() {}const fn = performance.timerify(myFunction);const obs = new PerformanceObserver((list) => {
console.log(list.getEntries()[0]);
obs.disconnect();
performance.clearFunctions();
});
obs.observe({ entryTypes: ['function'] });fn(); // Call the timerified function
As long as there is a PerformanceObserver subscribed to 'function' entry types, timing data will be added to the Performance Timeline every time the wrapped function is called.
One particularly fun way this can be used is to time the load time of every dependency in a Node.js application:
'use strict';const {
performance,
PerformanceObserver
} = require('perf_hooks');
const mod = require('module');// Monkey patch the require function
mod.Module.prototype.require =
performance.timerify(mod.Module.prototype.require);
require = performance.timerify(require);// Activate the observer
const obs = new PerformanceObserver((list) => {
const entries = list.getEntries();
entries.forEach((entry) => {
console.log(`require('${entry[0]}')`, entry.duration);
});
obs.disconnect(); // Free memory
performance.clearFunctions();
});obs.observe({ entryTypes: ['function'], buffered: true });require('some-module');
Measuring Garbage Collection
The implementation supports the ability to use thePerformanceObserver to track garbage collection events.
const {
performance,
PerformanceObserver
} = require('perf_hooks');const obs = new PerformanceObserver((list) => {
console.log(list.getEntries());
performance.clearGC();
});
obs.observe({ entryTypes: ['gc'] });
Every time a major or minor garbage collection kicks off while the PerformanceObserver is subscribed to 'gc' events, a new entry will be added to the Performance Timeline.
Querying the Timeline
To see what PerformanceEntry items have been added to the Performance timeline, the GetEntries() , GetEntriesByName() , and GetEntriesByType() methods may be used. These return optionally filtered arrays of PerformanceEntry instances. They are not, however, the most efficient means of monitoring the timeline.
The PerformanceObserver class provides a way of receiving callback notifications whenever a new PerformanceEntry instance is added. Notifications can be either synchronous:
const {
performance,
PerformanceObserver
} = require('perf_hooks');function callback(list, observer) {
console.log(list.getEntries());
observer.disconnect();
}const obs = new PerformanceObserver(callback);
obs.observe(( entryTypes: ['mark', 'measure'] });
Or asynchronous (using the buffered option):
const {
performance,
PerformanceObserver
} = require('perf_hooks');function callback(list, observer) {
console.log(list.getEntries());
observer.disconnect();
}const obs = new PerformanceObserver(callback);
obs.observe(( entryTypes: ['mark', 'measure'], buffered: true });
Whenever user code calls perf_hooks.performance.mark() or perf_hooks.performance.measure() while the PerformanceObserver is subscribed, the callback function passed to the constructor above will be invoked.
Just a quick example
There are a number of different ways in which the new API can be used. The example below uses a combination of the Async_hooks and Performance Timing APIs to measure exactly how long a Timeout handle takes to complete from Init to Destroy:
'use strict';
const async_hooks = require('async_hooks');
const {
performance,
PerformanceObserver
} = require('perf_hooks');const set = new Set();const hook = async_hooks.createHook({
init(id, type) {
if (type === 'Timeout') {
performance.mark(`Timeout-${id}-Init`);
set.add(id);
}
},
destroy(id) {
if (set.has(id)) {
set.delete(id);
performance.mark(`Timeout-${id}-Destroy`);
performance.measure(`Timeout-${id}`,
`Timeout-${id}-Init`,
`Timeout-${id}-Destroy`);
}
}
});hook.enable();const obs = new PerformanceObserver((list, observer) => {
console.log(list.getEntries()[0]);
performance.clearMarks();
performance.clearMeasures();
observer.disconnect();
});
obs.observe({ entryTypes: ['measure'], buffered: true });setTimeout(() => console.log('test'), 1000);
Details may change
Because this pull request is new, the specific details may change. I’ll try to update this post accordingly as things progress.
