diff options
author | Rebecca Turner <me@re-becca.org> | 2017-02-25 03:17:18 +0300 |
---|---|---|
committer | Rebecca Turner <me@re-becca.org> | 2017-04-15 06:16:22 +0300 |
commit | f5e8becd05e0426379eb0c999abdbc8e87a7f6f2 (patch) | |
tree | d2082596c8b85dba7278690f1f6e9f04628d2400 | |
parent | 8abb3c4e8f93892a3c60e51feb6c268eeb5605b4 (diff) |
npm: Add timing diagnostics on --loglevel=timing
-rw-r--r-- | Makefile | 10 | ||||
-rwxr-xr-x | bin/npm-cli.js | 2 | ||||
-rw-r--r-- | doc/misc/npm-config.md | 11 | ||||
-rw-r--r-- | lib/config/defaults.js | 4 | ||||
-rw-r--r-- | lib/install.js | 22 | ||||
-rw-r--r-- | lib/install/actions.js | 25 | ||||
-rw-r--r-- | lib/npm.js | 7 | ||||
-rw-r--r-- | lib/prune.js | 4 | ||||
-rw-r--r-- | lib/uninstall.js | 4 | ||||
-rw-r--r-- | lib/utils/error-handler.js | 60 | ||||
-rw-r--r-- | lib/utils/perf.js | 27 | ||||
-rw-r--r-- | package.json | 2 |
12 files changed, 131 insertions, 47 deletions
@@ -143,12 +143,12 @@ html/doc/misc/%.html: doc/misc/%.md $(html_docdeps) marked: node_modules/.bin/marked node_modules/.bin/marked: - node cli.js install marked --no-global + node cli.js install marked --no-global --no-timing marked-man: node_modules/.bin/marked-man node_modules/.bin/marked-man: - node cli.js install marked-man --no-global + node cli.js install marked-man --no-global --no-timing doc: man @@ -158,7 +158,7 @@ test: doc node cli.js test tag: - npm tag npm@$(PUBLISHTAG) latest + node bin/npm-cli.js tag npm@$(PUBLISHTAG) latest ls-ok: node . ls >/dev/null @@ -167,10 +167,10 @@ gitclean: git clean -fd publish: gitclean ls-ok link doc-clean doc - @git push origin :v$(shell npm -v) 2>&1 || true + @git push origin :v$(shell node bin/npm-cli.js --no-timing -v) 2>&1 || true git push origin $(BRANCH) &&\ git push origin --tags &&\ - npm publish --tag=$(PUBLISHTAG) + node bin/npm-cli.js publish --tag=$(PUBLISHTAG) release: gitclean ls-ok markedclean marked-manclean doc-clean doc node cli.js prune --production diff --git a/bin/npm-cli.js b/bin/npm-cli.js index 14937d64f..a83efdd54 100755 --- a/bin/npm-cli.js +++ b/bin/npm-cli.js @@ -57,7 +57,7 @@ if (conf.version) { console.log(npm.version) - return + return errorHandler.exit(0) } if (conf.versions) { diff --git a/doc/misc/npm-config.md b/doc/misc/npm-config.md index 463e6f192..4f987436d 100644 --- a/doc/misc/npm-config.md +++ b/doc/misc/npm-config.md @@ -960,6 +960,17 @@ Because other tools may rely on the convention that npm version tags look like `v1.0.0`, _only use this property if it is absolutely necessary_. In particular, use care when overriding this setting for public packages. +### timing + +* Default: `false` +* Type: Boolean + +If true, writes an `npm-debug` log to `_logs` and timing information to +`_timing.json`, both in your cache. `_timing.json` is a newline delimited +list of JSON objects. You can quickly view it with this +[json](https://www.npmjs.com/package/json) command line: +`json -g < ~/.npm/_timing.json`. + ### tmp * Default: TMPDIR environment variable, or "/tmp" diff --git a/lib/config/defaults.js b/lib/config/defaults.js index 96499d171..7758ee9b5 100644 --- a/lib/config/defaults.js +++ b/lib/config/defaults.js @@ -210,6 +210,7 @@ Object.defineProperty(exports, 'defaults', {get: function () { 'strict-ssl': true, tag: 'latest', 'tag-version-prefix': 'v', + timing: false, tmp: temp, unicode: hasUnicode(), 'unsafe-perm': process.platform === 'win32' || @@ -284,7 +285,7 @@ exports.types = { // local-address must be listed as an IP for a local network interface // must be IPv4 due to node bug 'local-address': getLocalAddresses(), - loglevel: ['silent', 'error', 'warn', 'http', 'info', 'verbose', 'silly'], + loglevel: ['silent', 'error', 'warn', 'http', 'timing', 'info', 'verbose', 'silly'], logstream: Stream, 'logs-max': Number, long: Boolean, @@ -324,6 +325,7 @@ exports.types = { 'sso-type': [null, 'oauth', 'saml'], 'strict-ssl': Boolean, tag: String, + timing: Boolean, tmp: path, unicode: Boolean, 'unsafe-perm': Boolean, diff --git a/lib/install.js b/lib/install.js index 43ba43663..a5a851a75 100644 --- a/lib/install.js +++ b/lib/install.js @@ -331,17 +331,15 @@ Installer.prototype.newTracker = function (tracker, name, size) { validate('OS', [tracker, name]) if (size) validate('N', [size]) this.progress[name] = tracker.newGroup(name, size) - var self = this return function (next) { - self.progress[name].silly(name, 'Starting') + process.emit('time', 'stage:' + name) next() } } Installer.prototype.finishTracker = function (name, cb) { validate('SF', arguments) - this.progress[name].silly(name, 'Finishing') - this.progress[name].finish() + process.emit('timeEnd', 'stage:' + name) cb() } @@ -355,7 +353,7 @@ Installer.prototype.loadCurrentTree = function (cb) { todo.push([this, this.readLocalPackageData]) } todo.push( - [this, this.normalizeTree, log.newGroup('normalizeTree')]) + [this, this.normalizeTree, log.newGroup('loadCurrentTree:normalizeTree')]) chain(todo, cb) } @@ -364,17 +362,17 @@ Installer.prototype.loadIdealTree = function (cb) { log.silly('install', 'loadIdealTree') chain([ - [this.newTracker(this.progress.loadIdealTree, 'cloneCurrentTree')], + [this.newTracker(this.progress.loadIdealTree, 'loadIdealTree:cloneCurrentTree')], [this, this.cloneCurrentTreeToIdealTree], - [this, this.finishTracker, 'cloneCurrentTree'], + [this, this.finishTracker, 'loadIdealTree:cloneCurrentTree'], - [this.newTracker(this.progress.loadIdealTree, 'loadShrinkwrap')], + [this.newTracker(this.progress.loadIdealTree, 'loadIdealTree:loadShrinkwrap')], [this, this.loadShrinkwrap], - [this, this.finishTracker, 'loadShrinkwrap'], + [this, this.finishTracker, 'loadIdealTree:loadShrinkwrap'], - [this.newTracker(this.progress.loadIdealTree, 'loadAllDepsIntoIdealTree', 10)], + [this.newTracker(this.progress.loadIdealTree, 'loadIdealTree:loadAllDepsIntoIdealTree', 10)], [this, this.loadAllDepsIntoIdealTree], - [this, this.finishTracker, 'loadAllDepsIntoIdealTree'], + [this, this.finishTracker, 'loadIdealTree:loadAllDepsIntoIdealTree'], // TODO: Remove this (should no longer be necessary, instead counter productive) [this, function (next) { recalculateMetadata(this.idealTree, log, next) }] @@ -386,7 +384,7 @@ Installer.prototype.loadAllDepsIntoIdealTree = function (cb) { log.silly('install', 'loadAllDepsIntoIdealTree') var saveDeps = getSaveType(this.args) - var cg = this.progress.loadAllDepsIntoIdealTree + var cg = this.progress['loadIdealTree:loadAllDepsIntoIdealTree'] var installNewModules = !!this.args.length var steps = [] diff --git a/lib/install/actions.js b/lib/install/actions.js index cb41217c0..acd542bbd 100644 --- a/lib/install/actions.js +++ b/lib/install/actions.js @@ -117,12 +117,23 @@ exports.doOne = function (cmd, staging, pkg, log, next) { execAction(prepareAction(staging, log)([cmd, pkg]), next) } +function time (log) { + process.emit('time', 'action:' + log.name) +} +function timeEnd (log) { + process.emit('timeEnd', 'action:' + log.name) +} + exports.doSerial = function (type, staging, actionsToRun, log, next) { validate('SSAOF', arguments) actionsToRun = actionsToRun .filter(function (value) { return value[0] === type }) log.silly('doSerial', '%s %d', type, actionsToRun.length) - chain(actionsToRun.map(prepareAction(staging, log)), andFinishTracker(log, next)) + time(log) + chain(actionsToRun.map(prepareAction(staging, log)), andFinishTracker(log, function () { + timeEnd(log) + next.apply(null, arguments) + })) } exports.doReverseSerial = function (type, staging, actionsToRun, log, next) { @@ -131,13 +142,21 @@ exports.doReverseSerial = function (type, staging, actionsToRun, log, next) { .filter(function (value) { return value[0] === type }) .reverse() log.silly('doReverseSerial', '%s %d', type, actionsToRun.length) - chain(actionsToRun.map(prepareAction(staging, log)), andFinishTracker(log, next)) + time(log) + chain(actionsToRun.map(prepareAction(staging, log)), andFinishTracker(log, function () { + timeEnd(log) + next.apply(null, arguments) + })) } exports.doParallel = function (type, staging, actionsToRun, log, next) { validate('SSAOF', arguments) actionsToRun = actionsToRun.filter(function (value) { return value[0] === type }) log.silly('doParallel', type + ' ' + actionsToRun.length) + time(log) - asyncMap(actionsToRun.map(prepareAction(staging, log)), execAction, andFinishTracker(log, next)) + asyncMap(actionsToRun.map(prepareAction(staging, log)), execAction, andFinishTracker(log, function () { + timeEnd(log) + next.apply(null, arguments) + })) } diff --git a/lib/npm.js b/lib/npm.js index f85288643..eadff8a69 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -38,6 +38,13 @@ var plumbing = require('./config/cmd-list').plumbing var output = require('./utils/output.js') var startMetrics = require('./utils/metrics.js').start + var perf = require('./utils/perf.js') + + log.addLevel('timing', 2500, { fg: 'green', bg: 'black' }) + perf.emit('time', 'npm') + perf.on('timing', function (name, finished) { + log.timing(name, 'Completed in', finished + 'ms') + }) npm.config = { loaded: false, diff --git a/lib/prune.js b/lib/prune.js index 6d103fc50..a590457a1 100644 --- a/lib/prune.js +++ b/lib/prune.js @@ -29,9 +29,9 @@ function Pruner (where, dryrun, args) { util.inherits(Pruner, Installer) Pruner.prototype.loadAllDepsIntoIdealTree = function (cb) { - log.silly('uninstall', 'loadAllDepsIntoIdealtree') + log.silly('uninstall', 'loadAllDepsIntoIdealTree') - var cg = this.progress.loadAllDepsIntoIdealTree + var cg = this.progress['loadIdealTree:loadAllDepsIntoIdealTree'] var steps = [] var self = this diff --git a/lib/uninstall.js b/lib/uninstall.js index 217604884..802cf7a28 100644 --- a/lib/uninstall.js +++ b/lib/uninstall.js @@ -63,10 +63,10 @@ Uninstaller.prototype.loadArgMetadata = function (next) { Uninstaller.prototype.loadAllDepsIntoIdealTree = function (cb) { validate('F', arguments) - log.silly('uninstall', 'loadAllDepsIntoIdealtree') + log.silly('uninstall', 'loadAllDepsIntoIdealTree') var saveDeps = getSaveType(this.args) - var cg = this.progress.loadAllDepsIntoIdealTree + var cg = this.progress['loadIdealTree:loadAllDepsIntoIdealTree'] var steps = [] steps.push( diff --git a/lib/utils/error-handler.js b/lib/utils/error-handler.js index 121390288..79c2ec5f2 100644 --- a/lib/utils/error-handler.js +++ b/lib/utils/error-handler.js @@ -1,5 +1,6 @@ module.exports = errorHandler +module.exports.exit = exit var cbCalled = false var log = require('npmlog') @@ -14,6 +15,7 @@ var writeFileAtomic = require('write-file-atomic') var errorMessage = require('./error-message.js') var stopMetrics = require('./metrics.js').stop var mkdirp = require('mkdirp') +var fs = require('graceful-fs') var logFileName function getLogFile () { @@ -23,9 +25,26 @@ function getLogFile () { return logFileName } +var timings = { + version: npm.version, + command: process.argv.slice(2), + logfile: null +} +process.on('timing', function (name, value) { + if (timings[name]) { timings[name] += value } else { timings[name] = value } +}) + process.on('exit', function (code) { + process.emit('timeEnd', 'npm') log.disableProgress() - if (!npm.config || !npm.config.loaded) return + if (npm.config.loaded && npm.config.get('timing')) { + try { + timings.logfile = getLogFile() + fs.appendFileSync(path.join(npm.config.get('cache'), '_timing.json'), JSON.stringify(timings) + '\n') + } catch (_) { + // ignore + } + } // kill any outstanding stats reporter if it hasn't finished yet stopMetrics() @@ -42,25 +61,26 @@ process.on('exit', function (code) { writeLogFile() } - if (wroteLogFile) { - // just a line break - if (log.levels[log.level] <= log.levels.error) console.error('') - - log.error( - '', - [ - 'A complete log of this run can be found in:', - ' ' + getLogFile() - ].join('\n') - ) - wroteLogFile = false - } if (code) { log.verbose('code', code) } } + if (npm.config.loaded && npm.config.get('timing') && !wroteLogFile) writeLogFile() + if (wroteLogFile) { + // just a line break + if (log.levels[log.level] <= log.levels.error) console.error('') + + log.error( + '', + [ + 'A complete log of this run can be found in:', + ' ' + getLogFile() + ].join('\n') + ) + wroteLogFile = false + } - var doExit = npm.config.get('_exit') + var doExit = npm.config.loaded && npm.config.get('_exit') if (doExit) { // actually exit. if (exitCode === 0 && !itWorked) { @@ -75,7 +95,7 @@ process.on('exit', function (code) { function exit (code, noLog) { exitCode = exitCode || process.exitCode || code - var doExit = npm.config ? npm.config.get('_exit') : true + var doExit = npm.config.loaded ? npm.config.get('_exit') : true log.verbose('exit', [code, doExit]) if (log.level === 'silent') noLog = true @@ -108,9 +128,6 @@ function exit (code, noLog) { function reallyExit (er) { if (er && !code) code = typeof er.errno === 'number' ? er.errno : 1 - // truncate once it's been written. - log.record.length = 0 - itWorked = !code // just emit a fake exit event. @@ -195,7 +212,6 @@ function errorHandler (er) { function writeLogFile () { if (wroteLogFile) return - wroteLogFile = true var os = require('os') @@ -214,6 +230,10 @@ function writeLogFile () { }) }) writeFileAtomic.sync(getLogFile(), logOutput) + + // truncate once it's been written. + log.record.length = 0 + wroteLogFile = true } catch (ex) { return } diff --git a/lib/utils/perf.js b/lib/utils/perf.js new file mode 100644 index 000000000..042326322 --- /dev/null +++ b/lib/utils/perf.js @@ -0,0 +1,27 @@ +'use strict' +var log = require('npmlog') +var EventEmitter = require('events').EventEmitter +var perf = new EventEmitter() +module.exports = perf + +var timings = {} + +process.on('time', time) +process.on('timeEnd', timeEnd) + +perf.on('time', time) +perf.on('timeEnd', timeEnd) + +function time (name) { + timings[name] = Date.now() +} + +function timeEnd (name) { + if (name in timings) { + process.emit('timing', name, Date.now() - timings[name]) + delete timings[name] + } else { + log.silly('timing', "Tried to end timer that doesn't exist:", name) + return + } +} diff --git a/package.json b/package.json index d117c9f2e..0254cfea8 100644 --- a/package.json +++ b/package.json @@ -219,7 +219,7 @@ }, "scripts": { "dumpconf": "env | grep npm | sort | uniq", - "prepare": "node bin/npm-cli.js prune --prefix=. --no-global && rimraf test/*/*/node_modules && make -j4 doc", + "prepare": "node bin/npm-cli.js --no-timing prune --prefix=. --no-global && rimraf test/*/*/node_modules && make -j4 doc", "preversion": "bash scripts/update-authors.sh && git add AUTHORS && git commit -m \"update AUTHORS\" || true", "tap": "tap --timeout 300", "tap-cover": "tap --nyc-arg='--cache' --coverage --timeout 600", |