diff options
author | James M Snell <jasnell@gmail.com> | 2017-08-07 15:53:24 -0700 |
---|---|---|
committer | James M Snell <jasnell@gmail.com> | 2017-08-23 16:00:09 -0700 |
commit | 67269fd7f33279699b1ae71225f3d738518c844c (patch) | |
tree | 22f6a615c02ccb93c69355d101db87f36f08cf06 /lib | |
parent | e007f66ae211192f385dc253bfa19a84e7fc649a (diff) | |
download | android-node-v8-67269fd7f33279699b1ae71225f3d738518c844c.tar.gz android-node-v8-67269fd7f33279699b1ae71225f3d738518c844c.tar.bz2 android-node-v8-67269fd7f33279699b1ae71225f3d738518c844c.zip |
perf_hooks: implementation of the perf timing API
An initial implementation of the Performance Timing API for Node.js.
This is the same Performance Timing API implemented by modern browsers
with a number of Node.js specific properties. The User Timing mark()
and measure() APIs are implemented, garbage collection timing, and
node startup milestone timing.
```js
const { performance } = require('perf_hooks');
performance.mark('A');
setTimeout(() => {
performance.mark('B');
performance.measure('A to B', 'A', 'B');
const entry = performance.getEntriesByName('A to B', 'measure')[0];
console.log(entry.duration);
}, 10000);
```
The implementation is at the native layer and makes use of uv_hrtime().
This should enable *eventual* integration with things like Tracing
and Inspection.
The implementation is extensible and should allow us to add new
performance entry types as we go (e.g. for measuring i/o perf,
etc).
Documentation and a test are provided.
PR-URL: https://github.com/nodejs/node/pull/14680
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Diffstat (limited to 'lib')
-rw-r--r-- | lib/internal/bootstrap_node.js | 38 | ||||
-rw-r--r-- | lib/internal/errors.js | 4 | ||||
-rw-r--r-- | lib/internal/module.js | 4 | ||||
-rw-r--r-- | lib/internal/process.js | 5 | ||||
-rw-r--r-- | lib/perf_hooks.js | 553 |
5 files changed, 599 insertions, 5 deletions
diff --git a/lib/internal/bootstrap_node.js b/lib/internal/bootstrap_node.js index 310db50960..50c630f84b 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -33,8 +33,21 @@ } const _process = NativeModule.require('internal/process'); + const perf = process.binding('performance'); + const { + NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE, + NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START, + NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END, + NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START, + NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END, + NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START, + NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END, + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START, + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END + } = perf.constants; _process.setup_hrtime(); + _process.setup_performance(); _process.setup_cpuUsage(); _process.setupMemoryUsage(); _process.setupConfig(NativeModule._source); @@ -106,7 +119,9 @@ // one to drop a file lib/_third_party_main.js into the build // directory which will be executed instead of Node's normal loading. process.nextTick(function() { + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START); NativeModule.require('_third_party_main'); + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END); }); } else if (process.argv[1] === 'inspect' || process.argv[1] === 'debug') { @@ -139,22 +154,30 @@ // channel. This needs to be done before any user code gets executed // (including preload modules). if (process.argv[1] && process.env.NODE_UNIQUE_ID) { + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START); const cluster = NativeModule.require('cluster'); cluster._setupWorker(); - + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END); // Make sure it's not accidentally inherited by child processes. delete process.env.NODE_UNIQUE_ID; } if (process._eval != null && !process._forceRepl) { + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START); + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END); // User passed '-e' or '--eval' arguments to Node without '-i' or // '--interactive' + + perf.markMilestone( + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START); preloadModules(); + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END); const internalModule = NativeModule.require('internal/module'); internalModule.addBuiltinLibsToObject(global); evalScript('[eval]'); } else if (process.argv[1] && process.argv[1] !== '-') { + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START); // make process.argv[1] into a full path const path = NativeModule.require('path'); process.argv[1] = path.resolve(process.argv[1]); @@ -170,11 +193,21 @@ checkScriptSyntax(source, filename); process.exit(0); } - + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END); + perf.markMilestone( + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START); preloadModules(); + perf.markMilestone( + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END); Module.runMain(); } else { + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START); + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END); + perf.markMilestone( + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START); preloadModules(); + perf.markMilestone( + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END); // If -i or --interactive were passed, or stdin is a TTY. if (process._forceRepl || NativeModule.require('tty').isatty(0)) { // REPL @@ -218,6 +251,7 @@ } } } + perf.markMilestone(NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE); } function setupProcessObject() { diff --git a/lib/internal/errors.js b/lib/internal/errors.js index 3eee337146..d270c3dd44 100644 --- a/lib/internal/errors.js +++ b/lib/internal/errors.js @@ -234,6 +234,7 @@ E('ERR_NO_CRYPTO', 'Node.js is not compiled with OpenSSL crypto support'); E('ERR_NO_ICU', '%s is not supported on Node.js compiled without ICU'); E('ERR_NO_LONGER_SUPPORTED', '%s is no longer supported'); E('ERR_PARSE_HISTORY_DATA', 'Could not parse history data in %s'); +E('ERR_INVALID_PERFORMANCE_MARK', 'The "%s" performance mark has not been set'); E('ERR_SOCKET_ALREADY_BOUND', 'Socket is already bound'); E('ERR_SOCKET_BAD_PORT', 'Port should be > 0 and < 65536'); E('ERR_SOCKET_BAD_TYPE', @@ -266,7 +267,8 @@ E('ERR_UNKNOWN_STDIN_TYPE', 'Unknown stdin file type'); E('ERR_UNKNOWN_STREAM_TYPE', 'Unknown stream file type'); E('ERR_V8BREAKITERATOR', 'Full ICU data not installed. ' + 'See https://github.com/nodejs/node/wiki/Intl'); - +E('ERR_VALID_PERFORMANCE_ENTRY_TYPE', + 'At least one valid performance entry type is required'); function invalidArgType(name, expected, actual) { assert(name, 'name is required'); diff --git a/lib/internal/module.js b/lib/internal/module.js index cf994b51c0..a6da58a8d7 100644 --- a/lib/internal/module.js +++ b/lib/internal/module.js @@ -79,8 +79,8 @@ function stripShebang(content) { const builtinLibs = [ 'assert', 'async_hooks', 'buffer', 'child_process', 'cluster', 'crypto', 'dgram', 'dns', 'domain', 'events', 'fs', 'http', 'https', 'net', - 'os', 'path', 'punycode', 'querystring', 'readline', 'repl', 'stream', - 'string_decoder', 'tls', 'tty', 'url', 'util', 'v8', 'vm', 'zlib' + 'os', 'path', 'perf_hooks', 'punycode', 'querystring', 'readline', 'repl', + 'stream', 'string_decoder', 'tls', 'tty', 'url', 'util', 'v8', 'vm', 'zlib' ]; const { exposeHTTP2 } = process.binding('config'); diff --git a/lib/internal/process.js b/lib/internal/process.js index 4935fcb264..c96f99ccfd 100644 --- a/lib/internal/process.js +++ b/lib/internal/process.js @@ -9,6 +9,10 @@ const assert = process.assert = function(x, msg) { }; +function setup_performance() { + require('perf_hooks'); +} + // Set up the process.cpuUsage() function. function setup_cpuUsage() { // Get the native function, which will be replaced with a JS version. @@ -258,6 +262,7 @@ function setupRawDebug() { } module.exports = { + setup_performance, setup_cpuUsage, setup_hrtime, setupMemoryUsage, diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js new file mode 100644 index 0000000000..4e7a0de7eb --- /dev/null +++ b/lib/perf_hooks.js @@ -0,0 +1,553 @@ +'use strict'; + +const { + PerformanceEntry, + mark: _mark, + measure: _measure, + milestones, + observerCounts, + setupObservers, + timeOrigin, + timerify, + constants +} = process.binding('performance'); + +const { + NODE_PERFORMANCE_ENTRY_TYPE_NODE, + NODE_PERFORMANCE_ENTRY_TYPE_MARK, + NODE_PERFORMANCE_ENTRY_TYPE_MEASURE, + NODE_PERFORMANCE_ENTRY_TYPE_GC, + NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION, + + NODE_PERFORMANCE_MILESTONE_NODE_START, + NODE_PERFORMANCE_MILESTONE_V8_START, + NODE_PERFORMANCE_MILESTONE_LOOP_START, + NODE_PERFORMANCE_MILESTONE_LOOP_EXIT, + NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE, + NODE_PERFORMANCE_MILESTONE_ENVIRONMENT, + NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START, + NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END, + NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START, + NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END, + NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START, + NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END, + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START, + NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END +} = constants; + +const L = require('internal/linkedlist'); +const kInspect = require('internal/util').customInspectSymbol; +const { inherits } = require('util'); + +const kCallback = Symbol('callback'); +const kTypes = Symbol('types'); +const kEntries = Symbol('entries'); +const kBuffer = Symbol('buffer'); +const kBuffering = Symbol('buffering'); +const kQueued = Symbol('queued'); +const kTimerified = Symbol('timerified'); +const kInsertEntry = Symbol('insert-entry'); +const kIndexEntry = Symbol('index-entry'); +const kClearEntry = Symbol('clear-entry'); +const kGetEntries = Symbol('get-entries'); +const kIndex = Symbol('index'); +const kMarks = Symbol('marks'); + +observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_MARK] = 1; +observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_MEASURE] = 1; +const observers = {}; +const observerableTypes = [ + 'node', + 'mark', + 'measure', + 'gc', + 'function' +]; + +let errors; +function lazyErrors() { + if (errors === undefined) + errors = require('internal/errors'); + return errors; +} + +function now() { + const hr = process.hrtime(); + return hr[0] * 1000 + hr[1] / 1e6; +} + +class PerformanceNodeTiming { + constructor() {} + + get name() { + return 'node'; + } + + get entryType() { + return 'node'; + } + + get startTime() { + return timeOrigin; + } + + get duration() { + return now() - timeOrigin; + } + + get nodeStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_NODE_START]; + } + + get v8Start() { + return milestones[NODE_PERFORMANCE_MILESTONE_V8_START]; + } + + get environment() { + return milestones[NODE_PERFORMANCE_MILESTONE_ENVIRONMENT]; + } + + get loopStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_START]; + } + + get loopExit() { + return milestones[NODE_PERFORMANCE_MILESTONE_LOOP_EXIT]; + } + + get bootstrapComplete() { + return milestones[NODE_PERFORMANCE_MILESTONE_BOOTSTRAP_COMPLETE]; + } + + get thirdPartyMainStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_START]; + } + + get thirdPartyMainEnd() { + return milestones[NODE_PERFORMANCE_MILESTONE_THIRD_PARTY_MAIN_END]; + } + + get clusterSetupStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_START]; + } + + get clusterSetupEnd() { + return milestones[NODE_PERFORMANCE_MILESTONE_CLUSTER_SETUP_END]; + } + + get moduleLoadStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_START]; + } + + get moduleLoadEnd() { + return milestones[NODE_PERFORMANCE_MILESTONE_MODULE_LOAD_END]; + } + + get preloadModuleLoadStart() { + return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_START]; + } + + get preloadModuleLoadEnd() { + return milestones[NODE_PERFORMANCE_MILESTONE_PRELOAD_MODULE_LOAD_END]; + } + + [kInspect]() { + return { + name: 'node', + entryType: 'node', + startTime: this.startTime, + duration: this.duration, + nodeStart: this.nodeStart, + v8Start: this.v8Start, + bootstrapComplete: this.bootstrapComplete, + environment: this.environment, + loopStart: this.loopStart, + loopExit: this.loopExit, + thirdPartyMainStart: this.thirdPartyMainStart, + thirdPartyMainEnd: this.thirdPartyMainEnd, + clusterSetupStart: this.clusterSetupStart, + clusterSetupEnd: this.clusterSetupEnd, + moduleLoadStart: this.moduleLoadStart, + moduleLoadEnd: this.moduleLoadEnd, + preloadModuleLoadStart: this.preloadModuleLoadStart, + preloadModuleLoadEnd: this.preloadModuleLoadEnd + }; + } +} +// Use this instead of Extends because we want PerformanceEntry in the +// prototype chain but we do not want to use the PerformanceEntry +// constructor for this. +inherits(PerformanceNodeTiming, PerformanceEntry); + +const nodeTiming = new PerformanceNodeTiming(); + +// Maintains a list of entries as a linked list stored in insertion order. +class PerformanceObserverEntryList { + constructor() { + Object.defineProperty(this, kEntries, { + writable: true, + enumerable: false, + value: {} + }); + L.init(this[kEntries]); + } + + [kInsertEntry](entry) { + const item = { entry }; + L.append(this[kEntries], item); + this[kIndexEntry](item); + } + + [kIndexEntry](entry) { + // Default implementation does nothing + } + + [kGetEntries](name, type) { + const ret = []; + const list = this[kEntries]; + if (!L.isEmpty(list)) { + let item = L.peek(list); + while (item && item !== list) { + const entry = item.entry; + if ((name && entry.name !== name) || + (type && entry.entryType !== type)) { + item = item._idlePrev; + continue; + } + sortedInsert(ret, entry); + item = item._idlePrev; + } + } + return ret; + } + + // While the items are stored in insertion order, getEntries() is + // required to return items sorted by startTime. + getEntries() { + return this[kGetEntries](); + } + + getEntriesByType(type) { + return this[kGetEntries](undefined, `${type}`); + } + + getEntriesByName(name, type) { + return this[kGetEntries](`${name}`, type !== undefined ? `${type}` : type); + } +} + +class PerformanceObserver { + constructor(callback) { + if (typeof callback !== 'function') { + const errors = lazyErrors(); + throw new errors.TypeError('ERR_INVALID_CALLBACK'); + } + Object.defineProperties(this, { + [kTypes]: { + enumerable: false, + writable: true, + value: {} + }, + [kCallback]: { + enumerable: false, + writable: true, + value: callback + }, + [kBuffer]: { + enumerable: false, + writable: true, + value: new PerformanceObserverEntryList() + }, + [kBuffering]: { + enumerable: false, + writable: true, + value: false + }, + [kQueued]: { + enumerable: false, + writable: true, + value: false + } + }); + } + + disconnect() { + const types = this[kTypes]; + const keys = Object.keys(types); + for (var n = 0; n < keys.length; n++) { + const item = types[keys[n]]; + if (item) { + L.remove(item); + observerCounts[keys[n]]--; + } + } + this[kTypes] = {}; + } + + observe(options) { + const errors = lazyErrors(); + if (typeof options !== 'object' || options == null) { + throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'options', 'Object'); + } + if (!Array.isArray(options.entryTypes)) { + throw new errors.TypeError('ERR_INVALID_OPT_VALUE', + 'entryTypes', options); + } + const entryTypes = options.entryTypes.filter(filterTypes).map(mapTypes); + if (entryTypes.length === 0) { + throw new errors.Error('ERR_VALID_PERFORMANCE_ENTRY_TYPE'); + } + this.disconnect(); + this[kBuffer][kEntries] = []; + L.init(this[kBuffer][kEntries]); + this[kBuffering] = Boolean(options.buffered); + for (var n = 0; n < entryTypes.length; n++) { + const entryType = entryTypes[n]; + const list = getObserversList(entryType); + const item = { obs: this }; + this[kTypes][entryType] = item; + L.append(list, item); + observerCounts[entryType]++; + } + } +} + +class Performance extends PerformanceObserverEntryList { + constructor() { + super(); + this[kIndex] = { + [kMarks]: new Set() + }; + this[kInsertEntry](nodeTiming); + } + + [kIndexEntry](item) { + const index = this[kIndex]; + const type = item.entry.entryType; + let items = index[type]; + if (!items) { + items = index[type] = {}; + L.init(items); + } + const entry = item.entry; + L.append(items, { entry, item }); + } + + [kClearEntry](type, name) { + const index = this[kIndex]; + const items = index[type]; + if (!items) return; + let item = L.peek(items); + while (item && item !== items) { + const entry = item.entry; + const next = item._idlePrev; + if (name !== undefined) { + if (entry.name === `${name}`) { + L.remove(item); // remove from the index + L.remove(item.item); // remove from the master + } + } else { + L.remove(item); // remove from the index + L.remove(item.item); // remove from the master + } + item = next; + } + } + + get nodeTiming() { + return nodeTiming; + } + + get timeOrigin() { + return timeOrigin; + } + + now() { + return now(); + } + + mark(name) { + name = `${name}`; + _mark(name); + this[kIndex][kMarks].add(name); + } + + measure(name, startMark, endMark) { + name = `${name}`; + endMark = `${endMark}`; + startMark = startMark !== undefined ? `${startMark}` : ''; + const marks = this[kIndex][kMarks]; + if (!marks.has(endMark) && !(endMark in nodeTiming)) { + const errors = lazyErrors(); + throw new errors.Error('ERR_INVALID_PERFORMANCE_MARK', endMark); + } + _measure(name, startMark, endMark); + } + + clearMarks(name) { + name = name !== undefined ? `${name}` : name; + this[kClearEntry]('mark', name); + if (name !== undefined) + this[kIndex][kMarks].delete(name); + else + this[kIndex][kMarks].clear(); + } + + clearMeasures(name) { + this[kClearEntry]('measure', name); + } + + clearGC() { + this[kClearEntry]('gc'); + } + + clearFunctions(name) { + this[kClearEntry]('function', name); + } + + timerify(fn) { + if (typeof fn !== 'function') { + const errors = lazyErrors(); + throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'fn', 'Function'); + } + if (fn[kTimerified]) + return fn[kTimerified]; + const ret = timerify(fn, fn.length); + Object.defineProperty(fn, kTimerified, { + enumerable: false, + configurable: true, + writable: false, + value: ret + }); + Object.defineProperties(ret, { + [kTimerified]: { + enumerable: false, + configurable: true, + writable: false, + value: ret + }, + name: { + enumerable: false, + configurable: true, + writable: false, + value: `timerified ${fn.name}` + } + }); + return ret; + } + + [kInspect]() { + return { + timeOrigin, + nodeTiming + }; + } +} + +const performance = new Performance(); + +function getObserversList(type) { + let list = observers[type]; + if (list === undefined) { + list = observers[type] = {}; + L.init(list); + } + return list; +} + +function doNotify() { + this[kQueued] = false; + this[kCallback](this[kBuffer], this); + this[kBuffer][kEntries] = []; + L.init(this[kBuffer][kEntries]); +} + +// Set up the callback used to receive PerformanceObserver notifications +function observersCallback(entry) { + const type = mapTypes(entry.entryType); + performance[kInsertEntry](entry); + const list = getObserversList(type); + + let current = L.peek(list); + + while (current && current.obs) { + const observer = current.obs; + // First, add the item to the observers buffer + const buffer = observer[kBuffer]; + buffer[kInsertEntry](entry); + // Second, check to see if we're buffering + if (observer[kBuffering]) { + // If we are, schedule a setImmediate call if one hasn't already + if (!observer[kQueued]) { + observer[kQueued] = true; + // Use setImmediate instead of nextTick to give more time + // for multiple entries to collect. + setImmediate(doNotify.bind(observer)); + } + } else { + // If not buffering, notify immediately + doNotify.call(observer); + } + current = current._idlePrev; + } +} +setupObservers(observersCallback); + +function filterTypes(i) { + return observerableTypes.indexOf(`${i}`) >= 0; +} + +function mapTypes(i) { + switch (i) { + case 'node': return NODE_PERFORMANCE_ENTRY_TYPE_NODE; + case 'mark': return NODE_PERFORMANCE_ENTRY_TYPE_MARK; + case 'measure': return NODE_PERFORMANCE_ENTRY_TYPE_MEASURE; + case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC; + case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION; + } +} + +// The specification requires that PerformanceEntry instances are sorted +// according to startTime. Unfortunately, they are not necessarily created +// in that same order, and can be reported to the JS layer in any order, +// which means we need to keep the list sorted as we insert. +function getInsertLocation(list, entryStartTime) { + let start = 0; + let end = list.length; + while (start < end) { + const pivot = (end + start) >>> 1; + if (list[pivot].startTime === entryStartTime) + return pivot; + if (list[pivot].startTime < entryStartTime) + start = pivot + 1; + else + end = pivot; + } + return start; +} + +function sortedInsert(list, entry) { + const entryStartTime = entry.startTime; + if (list.length === 0 || + (list[list.length - 1].startTime < entryStartTime)) { + list.push(entry); + return; + } + if (list[0] && (list[0].startTime > entryStartTime)) { + list.unshift(entry); + return; + } + const location = getInsertLocation(list, entryStartTime); + list.splice(location, 0, entry); +} + +module.exports = { + performance, + PerformanceObserver +}; + +Object.defineProperty(module.exports, 'constants', { + configurable: false, + enumerable: true, + value: constants +}); |