npm: Add timing diagnostics on --loglevel=timing

8 files changed, 113 insertions, 40 deletions

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
+  }
+}