diff --git a/lib/commands/ci.js b/lib/commands/ci.js index 9977c776ddf57..ff559b6d801d7 100644 --- a/lib/commands/ci.js +++ b/lib/commands/ci.js @@ -1,7 +1,7 @@ const reifyFinish = require('../utils/reify-finish.js') const runScript = require('@npmcli/run-script') const fs = require('fs/promises') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const validateLockfile = require('../utils/validate-lockfile.js') const ArboristWorkspaceCmd = require('../arborist-cmd.js') @@ -79,7 +79,7 @@ class CI extends ArboristWorkspaceCmd { if (!dryRun) { // Only remove node_modules after we've successfully loaded the virtual // tree and validated the lockfile - await this.npm.time('npm-ci:rm', async () => { + await time.start('npm-ci:rm', async () => { const path = `${where}/node_modules` // get the list of entries so we can skip the glob for performance const entries = await fs.readdir(path, null).catch(er => []) diff --git a/lib/npm.js b/lib/npm.js index 8449e2e2775a8..40be04e8b820b 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -11,7 +11,7 @@ const usage = require('./utils/npm-usage.js') const LogFile = require('./utils/log-file.js') const Timers = require('./utils/timers.js') const Display = require('./utils/display.js') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const { redactLog: replaceInfo } = require('@npmcli/redact') const updateNotifier = require('./utils/update-notifier.js') const pkg = require('../package.json') @@ -110,7 +110,7 @@ class Npm { async exec (cmd, args = this.argv) { const command = this.setCmd(cmd) - const timeEnd = this.time(`command:${cmd}`) + const timeEnd = time.start(`command:${cmd}`) // this is async but we dont await it, since its ok if it doesnt // finish before the command finishes running. it uses command and argv @@ -137,7 +137,7 @@ class Npm { async load () { if (!this.#loadPromise) { - this.#loadPromise = this.time('npm:load', () => this.#load().catch((er) => { + this.#loadPromise = time.start('npm:load', () => this.#load().catch((er) => { this.loadErr = er throw er })) @@ -158,10 +158,6 @@ class Npm { this.#logFile.off() } - time (name, fn) { - return this.#timers.time(name, fn) - } - writeTimingFile () { this.#timers.writeFile({ id: this.#runId, @@ -181,7 +177,7 @@ class Npm { } async #load () { - await this.time('npm:load:whichnode', async () => { + await time.start('npm:load:whichnode', async () => { // TODO should we throw here? const node = await which(process.argv[0]).catch(() => {}) if (node && node.toUpperCase() !== process.execPath.toUpperCase()) { @@ -191,7 +187,7 @@ class Npm { } }) - await this.time('npm:load:configload', () => this.config.load()) + await time.start('npm:load:configload', () => this.config.load()) // get createSupportsColor from chalk directly if this lands // https://github.com/chalk/chalk/pull/600 @@ -211,21 +207,21 @@ class Npm { // a different location. if this fails, then we don't have // a cache dir, but we don't want to fail immediately since // the command might not need a cache dir (like `npm --version`) - await this.time('npm:load:mkdirpcache', () => + await time.start('npm:load:mkdirpcache', () => fs.mkdir(this.cache, { recursive: true }) .catch((e) => log.verbose('cache', `could not create cache: ${e}`))) // it's ok if this fails. user might have specified an invalid dir // which we will tell them about at the end if (this.config.get('logs-max') > 0) { - await this.time('npm:load:mkdirplogs', () => + await time.start('npm:load:mkdirplogs', () => fs.mkdir(this.logsDir, { recursive: true }) .catch((e) => log.verbose('logfile', `could not create logs-dir: ${e}`))) } // note: this MUST be shorter than the actual argv length, because it // uses the same memory, so node will truncate it if it's too long. - this.time('npm:load:setTitle', () => { + time.start('npm:load:setTitle', () => { const { parsedArgv: { cooked, remain } } = this.config this.argv = remain // Secrets are mostly in configs, so title is set using only the positional args @@ -241,7 +237,7 @@ class Npm { log.verbose('argv', this.#argvClean.map(JSON.stringify).join(' ')) }) - this.time('npm:load:display', () => { + time.start('npm:load:display', () => { this.#display.load({ loglevel: this.config.get('loglevel'), // TODO: only pass in logColor and color and create chalk instances @@ -260,7 +256,7 @@ class Npm { process.env.COLOR = this.color ? '1' : '0' }) - this.time('npm:load:logFile', () => { + time.start('npm:load:logFile', () => { this.#logFile.load({ path: this.logPath, logsMax: this.config.get('logs-max'), @@ -268,13 +264,13 @@ class Npm { log.verbose('logfile', this.#logFile.files[0] || 'no logfile created') }) - this.time('npm:load:timers', () => + time.start('npm:load:timers', () => this.#timers.load({ path: this.config.get('timing') ? this.logPath : null, }) ) - this.time('npm:load:configScope', () => { + time.start('npm:load:configScope', () => { const configScope = this.config.get('scope') if (configScope && !/^@/.test(configScope)) { this.config.set('scope', `@${configScope}`, this.config.find('scope')) diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js index ce1bfaa54a56a..d63f7becc1cb9 100644 --- a/lib/utils/exit-handler.js +++ b/lib/utils/exit-handler.js @@ -1,6 +1,6 @@ const os = require('os') const fs = require('fs') -const { log, output } = require('proc-log') +const { log, output, time } = require('proc-log') const errorMessage = require('./error-message.js') const { redactLog: replaceInfo } = require('@npmcli/redact') @@ -11,14 +11,14 @@ let showLogFileError = false process.on('exit', code => { // process.emit is synchronous, so the timeEnd handler will run before the // unfinished timer check below - process.emit('timeEnd', 'npm') + time.end('npm') const hasLoadedNpm = npm?.config.loaded // Unfinished timers can be read before config load if (npm) { for (const [name, timer] of npm.unfinishedTimers) { - log.verbose('unfinished npm timer', name, timer) + log.silly('unfinished npm timer', name, timer) } } diff --git a/lib/utils/timers.js b/lib/utils/timers.js index 58ff39b6a1d66..2b8da90afbae9 100644 --- a/lib/utils/timers.js +++ b/lib/utils/timers.js @@ -1,6 +1,6 @@ const EE = require('events') const fs = require('fs') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const INITIAL_TIMER = 'npm' @@ -13,7 +13,7 @@ class Timers extends EE { constructor () { super() this.on() - process.emit('time', INITIAL_TIMER) + time.start(INITIAL_TIMER) this.started = this.#unfinished.get(INITIAL_TIMER) } @@ -26,23 +26,11 @@ class Timers extends EE { } on () { - process.on('time', this.#timeListener) - process.on('timeEnd', this.#timeEndListener) + process.on('time', this.#timeHandler) } off () { - process.off('time', this.#timeListener) - process.off('timeEnd', this.#timeEndListener) - } - - time (name, fn) { - process.emit('time', name) - const end = () => process.emit('timeEnd', name) - if (typeof fn === 'function') { - const res = fn() - return res && res.finally ? res.finally(end) : (end(), res) - } - return end + process.off('time', this.#timeHandler) } load ({ path } = {}) { @@ -75,18 +63,22 @@ class Timers extends EE { } } - #timeListener = (name) => { - this.#unfinished.set(name, Date.now()) - } - - #timeEndListener = (name) => { - if (this.#unfinished.has(name)) { - const ms = Date.now() - this.#unfinished.get(name) - this.#finished[name] = ms - this.#unfinished.delete(name) - log.timing(name, `Completed in ${ms}ms`) - } else { - log.silly('timing', "Tried to end timer that doesn't exist:", name) + #timeHandler = (level, name) => { + const now = Date.now() + switch (level) { + case time.KEYS.start: + this.#unfinished.set(name, now) + break + case time.KEYS.end: { + if (this.#unfinished.has(name)) { + const ms = now - this.#unfinished.get(name) + this.#finished[name] = ms + this.#unfinished.delete(name) + log.timing(name, `Completed in ${ms}ms`) + } else { + log.silly('timing', "Tried to end timer that doesn't exist:", name) + } + } } } } diff --git a/test/lib/npm.js b/test/lib/npm.js index 59400ce8da9f1..a0dec04caa137 100644 --- a/test/lib/npm.js +++ b/test/lib/npm.js @@ -1,6 +1,7 @@ const t = require('tap') const { resolve, dirname, join } = require('path') const fs = require('fs') +const { time } = require('proc-log') const { load: loadMockNpm } = require('../fixtures/mock-npm.js') const mockGlobals = require('@npmcli/mock-globals') const { commands } = require('../../lib/utils/cmd-list.js') @@ -398,15 +399,15 @@ t.test('timings', async t => { timing: true, }, }) - process.emit('time', 'foo') - process.emit('time', 'bar') + time.start('foo') + time.start('bar') t.match(npm.unfinishedTimers.get('foo'), Number, 'foo timer is a number') t.match(npm.unfinishedTimers.get('bar'), Number, 'foo timer is a number') - process.emit('timeEnd', 'foo') - process.emit('timeEnd', 'bar') - process.emit('timeEnd', 'baz') + time.end('foo') + time.end('bar') + time.end('baz') // npm timer is started by default - process.emit('timeEnd', 'npm') + time.end('npm') t.match(logs.timing.byTitle('foo'), [ /Completed in [0-9]+ms/, ]) @@ -428,9 +429,9 @@ t.test('timings', async t => { const { npm, cache, timingFile } = await loadMockNpm(t, { config: { timing: true }, }) - process.emit('time', 'foo') - process.emit('timeEnd', 'foo') - process.emit('time', 'bar') + time.start('foo') + time.end('foo') + time.start('bar') npm.writeTimingFile() t.match(npm.timingFile, cache) t.match(npm.timingFile, /-timing.json$/) diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 8af47d9abc26c..b82a8c6ab266a 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -3,7 +3,7 @@ const fs = require('fs') const fsMiniPass = require('fs-minipass') const { join, resolve } = require('path') const EventEmitter = require('events') -const { output } = require('proc-log') +const { output, time } = require('proc-log') const { load: loadMockNpm } = require('../../fixtures/mock-npm') const mockGlobals = require('@npmcli/mock-globals') const { cleanCwd, cleanDate } = require('../../fixtures/clean-snapshot') @@ -517,8 +517,8 @@ t.test('unfinished timers', async (t) => { config: { timing: true }, }) - process.emit('time', 'foo') - process.emit('time', 'bar') + time.start('foo') + time.start('bar') await exitHandler() const timingFileData = await timingFile() diff --git a/test/lib/utils/timers.js b/test/lib/utils/timers.js index c395a92a0a3e7..1901738feb975 100644 --- a/test/lib/utils/timers.js +++ b/test/lib/utils/timers.js @@ -1,7 +1,7 @@ const t = require('tap') const { resolve, join } = require('path') const fs = require('graceful-fs') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const tmock = require('../../fixtures/tmock') const mockTimers = (t, options) => { @@ -24,30 +24,19 @@ const mockTimers = (t, options) => { t.test('listens/stops on process', async (t) => { const { timers } = mockTimers(t) - process.emit('time', 'foo') - process.emit('time', 'bar') - process.emit('timeEnd', 'bar') + time.start('foo') + time.start('bar') + time.end('bar') t.match(timers.unfinished, new Map([['foo', Number]])) t.match(timers.finished, { bar: Number }) timers.off() - process.emit('time', 'baz') + time.start('baz') t.notOk(timers.unfinished.get('baz')) }) -t.test('convenience time method', async (t) => { - const { timers } = mockTimers(t) - - const end = timers.time('later') - timers.time('sync', () => {}) - await timers.time('async', () => new Promise(r => setTimeout(r, 10))) - end() - - t.match(timers.finished, { later: Number, sync: Number, async: Number }) -}) - t.test('initial timer is named npm', async (t) => { const { timers } = mockTimers(t) - process.emit('timeEnd', 'npm') + time.end('npm') t.match(timers.finished, { npm: Number }) }) @@ -55,26 +44,26 @@ t.test('logs timing events', async (t) => { const events = [] const listener = (...args) => events.push(args) const { timers, logs } = mockTimers(t, { listener }) - process.emit('time', 'foo') - process.emit('time', 'bar') - process.emit('timeEnd', 'bar') + time.start('foo') + time.start('bar') + time.end('bar') timers.off(listener) - process.emit('timeEnd', 'foo') + time.end('foo') t.equal(logs.timing.length, 1) t.match(logs.timing[0], /^bar Completed in [0-9]ms/) }) t.test('finish unstarted timer', async (t) => { const { logs } = mockTimers(t) - process.emit('timeEnd', 'foo') + time.end('foo') t.match(logs.silly, ["timing Tried to end timer that doesn't exist: foo"]) }) t.test('writes file', async (t) => { const { timers } = mockTimers(t) const dir = t.testdir() - process.emit('time', 'foo') - process.emit('timeEnd', 'foo') + time.start('foo') + time.end('foo') timers.load({ path: resolve(dir, `TIMING_FILE-`) }) timers.writeFile({ some: 'data' }) const data = JSON.parse(fs.readFileSync(resolve(dir, 'TIMING_FILE-timing.json'))) diff --git a/workspaces/arborist/bin/index.js b/workspaces/arborist/bin/index.js index ff356fafab7c3..414c7eb468cd8 100755 --- a/workspaces/arborist/bin/index.js +++ b/workspaces/arborist/bin/index.js @@ -2,6 +2,7 @@ const fs = require('fs') const path = require('path') +const { time } = require('proc-log') const { bin, arb: options } = require('./lib/options') const version = require('../package.json').version @@ -72,11 +73,11 @@ for (const file of commandFiles) { log.info(name, options) - process.emit('time', totalTime) - process.emit('time', scriptTime) + const timeEnd = time.start(totalTime) + const scriptEnd = time.start(scriptTime) return command(options, (result) => { - process.emit('timeEnd', scriptTime) + scriptEnd() return { result, timing: { @@ -95,7 +96,7 @@ for (const file of commandFiles) { return err }) .then((r) => { - process.emit('timeEnd', totalTime) + timeEnd() if (bin.loglevel !== 'silent') { console[process.exitCode ? 'error' : 'log'](r) } diff --git a/workspaces/arborist/bin/lib/timers.js b/workspaces/arborist/bin/lib/timers.js index 586dee7806dd0..a7ec534f5c5a7 100644 --- a/workspaces/arborist/bin/lib/timers.js +++ b/workspaces/arborist/bin/lib/timers.js @@ -4,22 +4,22 @@ const log = require('./logging.js') const timers = new Map() const finished = new Map() -process.on('time', name => { - if (timers.has(name)) { - throw new Error('conflicting timer! ' + name) - } - timers.set(name, process.hrtime.bigint()) -}) - -process.on('timeEnd', name => { - if (!timers.has(name)) { - throw new Error('timer not started! ' + name) - } - const elapsed = Number(process.hrtime.bigint() - timers.get(name)) - timers.delete(name) - finished.set(name, elapsed) - if (options.timing) { - log.info('timeEnd', `${name} ${elapsed / 1e9}s`, log.meta({ force: options.timing === 'always' })) +process.on('time', (level, name) => { + if (level === 'start') { + if (timers.has(name)) { + throw new Error('conflicting timer! ' + name) + } + timers.set(name, process.hrtime.bigint()) + } else if (level === 'end') { + if (!timers.has(name)) { + throw new Error('timer not started! ' + name) + } + const elapsed = Number(process.hrtime.bigint() - timers.get(name)) + timers.delete(name) + finished.set(name, elapsed) + if (options.timing) { + log.info('timeEnd', `${name} ${elapsed / 1e9}s`, log.meta({ force: options.timing === 'always' })) + } } }) diff --git a/workspaces/arborist/lib/arborist/build-ideal-tree.js b/workspaces/arborist/lib/arborist/build-ideal-tree.js index 1daf03b0b466c..ac3062928ebd8 100644 --- a/workspaces/arborist/lib/arborist/build-ideal-tree.js +++ b/workspaces/arborist/lib/arborist/build-ideal-tree.js @@ -11,7 +11,7 @@ const treeCheck = require('../tree-check.js') const { readdirScoped } = require('@npmcli/fs') const { lstat, readlink } = require('fs/promises') const { depth } = require('treeverse') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const { redact } = require('@npmcli/redact') const { @@ -179,7 +179,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { options.rm = null } - process.emit('time', 'idealTree') + const timeEnd = time.start('idealTree') if (!options.add && !options.rm && !options.update && this.options.global) { throw new Error('global requires add, rm, or update option') @@ -205,7 +205,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { await this.#pruneFailedOptional() await this.#checkEngineAndPlatform() } finally { - process.emit('timeEnd', 'idealTree') + timeEnd() this.finishTracker('idealTree') } @@ -278,7 +278,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { // load the initial tree, either the virtualTree from a shrinkwrap, // or just the root node from a package.json async #initTree () { - process.emit('time', 'idealTree:init') + const timeEnd = time.start('idealTree:init') let root if (this.options.global) { root = await this.#globalRootNode() @@ -356,7 +356,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { // if you want another one, load another copy. this.idealTree = tree this.virtualTree = null - process.emit('timeEnd', 'idealTree:init') + timeEnd() return tree }) } @@ -420,7 +420,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { // process the add/rm requests by modifying the root node, and the // update.names request by queueing nodes dependent on those named. async #applyUserRequests (options) { - process.emit('time', 'idealTree:userRequests') + const timeEnd = time.start('idealTree:userRequests') const tree = this.idealTree.target if (!this.options.workspaces.length) { @@ -436,7 +436,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { await Promise.all(appliedRequests) } - process.emit('timeEnd', 'idealTree:userRequests') + timeEnd() } async #applyUserRequestsToNode (tree, options) { @@ -691,7 +691,7 @@ module.exports = cls => class IdealTreeBuilder extends cls { // if the lockfile is from node v5 or earlier, then we'll have to reload // all the manifests of everything we encounter. this is costly, but at // least it's just a one-time hit. - process.emit('time', 'idealTree:inflate') + const timeEnd = time.start('idealTree:inflate') // don't warn if we're not gonna actually write it back anyway. const heading = ancient ? 'ancient lockfile' : 'old lockfile' @@ -758,14 +758,14 @@ This is a one-time fix-up, please be patient... meta.originalLockfileVersion = defaultLockfileVersion } this.finishTracker('idealTree:inflate') - process.emit('timeEnd', 'idealTree:inflate') + timeEnd() } // at this point we have a virtual tree with the actual root node's // package deps, which may be partly or entirely incomplete, invalid // or extraneous. #buildDeps () { - process.emit('time', 'idealTree:buildDeps') + const timeEnd = time.start('idealTree:buildDeps') const tree = this.idealTree.target tree.assertRootOverrides() this.#depsQueue.push(tree) @@ -773,15 +773,14 @@ This is a one-time fix-up, please be patient... // in the override list log.silly('idealTree', 'buildDeps') this.addTracker('idealTree', tree.name, '') - return this.#buildDepStep() - .then(() => process.emit('timeEnd', 'idealTree:buildDeps')) + return this.#buildDepStep().then(timeEnd) } async #buildDepStep () { // removes tracker of previous dependency in the queue if (this.#currentDep) { const { location, name } = this.#currentDep - process.emit('timeEnd', `idealTree:${location || '#root'}`) + time.end(`idealTree:${location || '#root'}`) this.finishTracker('idealTree', name, location) this.#currentDep = null } @@ -807,7 +806,7 @@ This is a one-time fix-up, please be patient... this.#depsSeen.add(node) this.#currentDep = node - process.emit('time', `idealTree:${node.location || '#root'}`) + time.start(`idealTree:${node.location || '#root'}`) // if we're loading a _complete_ ideal tree, for a --package-lock-only // installation for example, we have to crack open the tarball and @@ -1449,7 +1448,7 @@ This is a one-time fix-up, please be patient... } #fixDepFlags () { - process.emit('time', 'idealTree:fixDepFlags') + const timeEnd = time.start('idealTree:fixDepFlags') const metaFromDisk = this.idealTree.meta.loadedFromDisk const flagsSuspect = this[_flagsSuspect] const mutateTree = this.#mutateTree @@ -1496,7 +1495,7 @@ This is a one-time fix-up, please be patient... } } - process.emit('timeEnd', 'idealTree:fixDepFlags') + timeEnd() } #idealTreePrune () { diff --git a/workspaces/arborist/lib/arborist/index.js b/workspaces/arborist/lib/arborist/index.js index 0f02e1df1582f..3726b1ecaf633 100644 --- a/workspaces/arborist/lib/arborist/index.js +++ b/workspaces/arborist/lib/arborist/index.js @@ -30,7 +30,7 @@ const { resolve } = require('path') const { homedir } = require('os') const { depth } = require('treeverse') const mapWorkspaces = require('@npmcli/map-workspaces') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const { saveTypeMap } = require('../add-rm-pkg-deps.js') const AuditReport = require('../audit-report.js') @@ -66,7 +66,7 @@ const lockfileVersion = lfv => { class Arborist extends Base { constructor (options = {}) { - process.emit('time', 'arborist:ctor') + const timeEnd = time.start('arborist:ctor') super(options) this.options = { nodeVersion: process.version, @@ -97,7 +97,7 @@ class Arborist extends Base { } this.cache = resolve(this.options.cache) this.path = resolve(this.options.path) - process.emit('timeEnd', 'arborist:ctor') + timeEnd() } // TODO: We should change these to static functions instead @@ -223,7 +223,7 @@ class Arborist extends Base { // XXX: deprecate separate method options objects. options = { ...this.options, ...options } - process.emit('time', 'audit') + const timeEnd = time.start('audit') let tree if (options.packageLock === false) { // build ideal tree @@ -246,7 +246,7 @@ class Arborist extends Base { } this.auditReport = await AuditReport.load(tree, options) const ret = options.fix ? this.reify(options) : this.auditReport - process.emit('timeEnd', 'audit') + timeEnd() this.finishTracker('audit') return ret } diff --git a/workspaces/arborist/lib/arborist/rebuild.js b/workspaces/arborist/lib/arborist/rebuild.js index 36dc6ae790fe6..4f8730cde7f38 100644 --- a/workspaces/arborist/lib/arborist/rebuild.js +++ b/workspaces/arborist/lib/arborist/rebuild.js @@ -9,11 +9,8 @@ const binLinks = require('bin-links') const runScript = require('@npmcli/run-script') const { callLimit: promiseCallLimit } = require('promise-call-limit') const { resolve } = require('path') -const { - isNodeGypPackage, - defaultGypInstallScript, -} = require('@npmcli/node-gyp') -const { log } = require('proc-log') +const { isNodeGypPackage, defaultGypInstallScript } = require('@npmcli/node-gyp') +const { log, time } = require('proc-log') const boolEnv = b => b ? '1' : '' const sortNodes = (a, b) => @@ -54,7 +51,7 @@ module.exports = cls => class Builder extends cls { // separates links nodes so that it can run // prepare scripts and link bins in the expected order - process.emit('time', 'build') + const timeEnd = time.start('build') const { depNodes, @@ -70,7 +67,7 @@ module.exports = cls => class Builder extends cls { await this.#build(linkNodes, { type: 'links' }) } - process.emit('timeEnd', 'build') + timeEnd() } // if we don't have a set of nodes, then just rebuild @@ -147,7 +144,7 @@ module.exports = cls => class Builder extends cls { } async #build (nodes, { type = 'deps' }) { - process.emit('time', `build:${type}`) + const timeEnd = time.start(`build:${type}`) await this.#buildQueues(nodes) @@ -168,11 +165,11 @@ module.exports = cls => class Builder extends cls { await this.#runScripts('postinstall') } - process.emit('timeEnd', `build:${type}`) + timeEnd() } async #buildQueues (nodes) { - process.emit('time', 'build:queue') + const timeEnd = time.start('build:queue') const set = new Set() const promises = [] @@ -210,7 +207,7 @@ module.exports = cls => class Builder extends cls { } } } - process.emit('timeEnd', 'build:queue') + timeEnd() } async [_checkBins] (node) { @@ -286,7 +283,7 @@ module.exports = cls => class Builder extends cls { return } - process.emit('time', `build:run:${event}`) + const timeEnd = time.start(`build:run:${event}`) const stdio = this.options.foregroundScripts ? 'inherit' : 'pipe' const limit = this.options.foregroundScripts ? 1 : undefined await promiseCallLimit(queue.map(node => async () => { @@ -309,8 +306,7 @@ module.exports = cls => class Builder extends cls { return } - const timer = `build:run:${event}:${location}` - process.emit('time', timer) + const timeEndLocation = time.start(`build:run:${event}:${location}`) log.info('run', pkg._id, event, location, pkg.scripts[event]) const env = { npm_package_resolved: resolved, @@ -356,9 +352,9 @@ module.exports = cls => class Builder extends cls { ? this[_handleOptionalFailure](node, p) : p) - process.emit('timeEnd', timer) + timeEndLocation() }), { limit }) - process.emit('timeEnd', `build:run:${event}`) + timeEnd() } async #linkAllBins () { @@ -367,7 +363,7 @@ module.exports = cls => class Builder extends cls { return } - process.emit('time', 'build:link') + const timeEnd = time.start('build:link') const promises = [] // sort the queue by node path, so that the module-local collision // detector in bin-links will always resolve the same way. @@ -377,7 +373,7 @@ module.exports = cls => class Builder extends cls { } await promiseAllRejectLate(promises) - process.emit('timeEnd', 'build:link') + timeEnd() } async #createBinLinks (node) { @@ -385,7 +381,7 @@ module.exports = cls => class Builder extends cls { return } - process.emit('time', `build:link:${node.location}`) + const timeEnd = time.start(`build:link:${node.location}`) const p = binLinks({ pkg: node.package, @@ -399,6 +395,6 @@ module.exports = cls => class Builder extends cls { ? this[_handleOptionalFailure](node, p) : p) - process.emit('timeEnd', `build:link:${node.location}`) + timeEnd() } } diff --git a/workspaces/arborist/lib/arborist/reify.js b/workspaces/arborist/lib/arborist/reify.js index 81b81cfd2d665..42bbdfef8eb42 100644 --- a/workspaces/arborist/lib/arborist/reify.js +++ b/workspaces/arborist/lib/arborist/reify.js @@ -7,7 +7,7 @@ const npa = require('npm-package-arg') const semver = require('semver') const debug = require('../debug.js') const { walkUp } = require('walk-up-path') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const hgi = require('hosted-git-info') const rpj = require('read-package-json-fast') @@ -149,7 +149,7 @@ module.exports = cls => class Reifier extends cls { // start tracker block this.addTracker('reify') - process.emit('time', 'reify') + const timeEnd = time.start('reify') await this[_validatePath]() await this[_loadTrees](options) @@ -174,7 +174,7 @@ module.exports = cls => class Reifier extends cls { this.auditReport = await this.auditReport this.finishTracker('reify') - process.emit('timeEnd', 'reify') + timeEnd() return treeCheck(this.actualTree) } @@ -269,7 +269,7 @@ module.exports = cls => class Reifier extends cls { // when doing a local install, we load everything and figure it all out. // when doing a global install, we *only* care about the explicit requests. [_loadTrees] (options) { - process.emit('time', 'reify:loadTrees') + const timeEnd = time.start('reify:loadTrees') const bitOpt = { ...options, complete: this[_packageLockOnly] || this[_dryRun], @@ -277,8 +277,7 @@ module.exports = cls => class Reifier extends cls { // if we're only writing a package lock, then it doesn't matter what's here if (this[_packageLockOnly]) { - return this.buildIdealTree(bitOpt) - .then(() => process.emit('timeEnd', 'reify:loadTrees')) + return this.buildIdealTree(bitOpt).then(timeEnd) } const actualOpt = this.options.global ? { @@ -312,7 +311,7 @@ module.exports = cls => class Reifier extends cls { return Promise.all([ this.loadActual(actualOpt), this.buildIdealTree(bitOpt), - ]).then(() => process.emit('timeEnd', 'reify:loadTrees')) + ]).then(timeEnd) } // the global install space tends to have a lot of stuff in it. don't @@ -322,7 +321,7 @@ module.exports = cls => class Reifier extends cls { // explicitRequests which is set during buildIdealTree return this.buildIdealTree(bitOpt) .then(() => this.loadActual(actualOpt)) - .then(() => process.emit('timeEnd', 'reify:loadTrees')) + .then(timeEnd) } [_diffTrees] () { @@ -330,7 +329,7 @@ module.exports = cls => class Reifier extends cls { return } - process.emit('time', 'reify:diffTrees') + const timeEnd = time.start('reify:diffTrees') // XXX if we have an existing diff already, there should be a way // to just invalidate the parts that changed, but avoid walking the // whole tree again. @@ -397,7 +396,7 @@ module.exports = cls => class Reifier extends cls { // because if we remove node_modules/FOO on case-insensitive systems, // it will remove the dep that we *want* at node_modules/foo. - process.emit('timeEnd', 'reify:diffTrees') + timeEnd() } // add the node and all its bins to the list of things to be @@ -422,7 +421,7 @@ module.exports = cls => class Reifier extends cls { // move aside the shallowest nodes in the tree that have to be // changed or removed, so that we can rollback if necessary. [_retireShallowNodes] () { - process.emit('time', 'reify:retireShallow') + const timeEnd = time.start('reify:retireShallow') const moves = this[_retiredPaths] = {} for (const diff of this.diff.children) { if (diff.action === 'CHANGE' || diff.action === 'REMOVE') { @@ -433,8 +432,7 @@ module.exports = cls => class Reifier extends cls { log.silly('reify', 'moves', moves) const movePromises = Object.entries(moves) .map(([from, to]) => this[_renamePath](from, to)) - return promiseAllRejectLate(movePromises) - .then(() => process.emit('timeEnd', 'reify:retireShallow')) + return promiseAllRejectLate(movePromises).then(timeEnd) } [_renamePath] (from, to, didMkdirp = false) { @@ -456,14 +454,14 @@ module.exports = cls => class Reifier extends cls { } [_rollbackRetireShallowNodes] (er) { - process.emit('time', 'reify:rollback:retireShallow') + const timeEnd = time.start('reify:rollback:retireShallow') const moves = this[_retiredPaths] const movePromises = Object.entries(moves) .map(([from, to]) => this[_renamePath](to, from)) return promiseAllRejectLate(movePromises) // ignore subsequent rollback errors .catch(er => {}) - .then(() => process.emit('timeEnd', 'reify:rollback:retireShallow')) + .then(timeEnd) .then(() => { throw er }) @@ -476,7 +474,7 @@ module.exports = cls => class Reifier extends cls { return } - process.emit('time', 'reify:trashOmits') + const timeEnd = time.start('reify:trashOmits') for (const node of this.idealTree.inventory.values()) { const { top } = node @@ -503,11 +501,11 @@ module.exports = cls => class Reifier extends cls { } } - process.emit('timeEnd', 'reify:trashOmits') + timeEnd() } [_createSparseTree] () { - process.emit('time', 'reify:createSparse') + const timeEnd = time.start('reify:createSparse') // if we call this fn again, we look for the previous list // so that we can avoid making the same directory multiple times const leaves = this.diff.leaves @@ -550,12 +548,11 @@ module.exports = cls => class Reifier extends cls { if (made) { this[_sparseTreeRoots].add(made) } - })) - .then(() => process.emit('timeEnd', 'reify:createSparse')) + })).then(timeEnd) } [_rollbackCreateSparseTree] (er) { - process.emit('time', 'reify:rollback:createSparse') + const timeEnd = time.start('reify:rollback:createSparse') // cut the roots of the sparse tree that were created, not the leaves const roots = this[_sparseTreeRoots] // also delete the moves that we retired, so that we can move them back @@ -569,7 +566,7 @@ module.exports = cls => class Reifier extends cls { log.warn('cleanup', 'Failed to remove some directories', failures) } }) - .then(() => process.emit('timeEnd', 'reify:rollback:createSparse')) + .then(timeEnd) .then(() => this[_rollbackRetireShallowNodes](er)) } @@ -587,7 +584,7 @@ module.exports = cls => class Reifier extends cls { return } - process.emit('time', 'reify:loadShrinkwraps') + const timeEnd = time.start('reify:loadShrinkwraps') const Arborist = this.constructor return promiseAllRejectLate(shrinkwraps.map(diff => { @@ -604,7 +601,7 @@ module.exports = cls => class Reifier extends cls { .then(() => this[_createSparseTree]()) .then(() => this[_addOmitsToTrashList]()) .then(() => this[_loadShrinkwrapsAndUpdateTrees]()) - .then(() => process.emit('timeEnd', 'reify:loadShrinkwraps')) + .then(timeEnd) } // create a symlink for Links, extract for Nodes @@ -619,8 +616,7 @@ module.exports = cls => class Reifier extends cls { return node } - const timer = `reifyNode:${node.location}` - process.emit('time', timer) + const timeEnd = time.start(`reifyNode:${node.location}`) this.addTracker('reify', node.name, node.location) const { npmVersion, nodeVersion, cpu, os, libc } = this.options @@ -643,7 +639,7 @@ module.exports = cls => class Reifier extends cls { return this[_handleOptionalFailure](node, p) .then(() => { this.finishTracker('reify', node.name, node.location) - process.emit('timeEnd', timer) + timeEnd() return node }) } @@ -786,7 +782,7 @@ module.exports = cls => class Reifier extends cls { depth = 0, bundlesByDepth = this[_getBundlesByDepth]() ) { if (depth === 0) { - process.emit('time', 'reify:loadBundles') + time.start('reify:loadBundles') } const maxBundleDepth = bundlesByDepth.get('maxBundleDepth') @@ -796,7 +792,7 @@ module.exports = cls => class Reifier extends cls { this[_pruneBundledMetadeps](bundlesByDepth) this[_diffTrees]() } - process.emit('timeEnd', 'reify:loadBundles') + time.end('reify:loadBundles') return } @@ -981,7 +977,7 @@ module.exports = cls => class Reifier extends cls { // before finishing the reify() and returning the tree. Thus, we do // NOT return the promise, as the intent is for this to run in parallel // with the reification, and be resolved at a later time. - process.emit('time', 'reify:audit') + const timeEnd = time.start('reify:audit') const options = { ...this.options } const tree = this.idealTree @@ -995,7 +991,7 @@ module.exports = cls => class Reifier extends cls { } this.auditReport = AuditReport.load(tree, options).then(res => { - process.emit('timeEnd', 'reify:audit') + timeEnd() return res }) } @@ -1005,7 +1001,7 @@ module.exports = cls => class Reifier extends cls { // kicking off each unpack job. If any fail, we rm the sparse // tree entirely and try to put everything back where it was. [_unpackNewModules] () { - process.emit('time', 'reify:unpack') + const timeEnd = time.start('reify:unpack') const unpacks = [] dfwalk({ tree: this.diff, @@ -1038,8 +1034,7 @@ module.exports = cls => class Reifier extends cls { }, getChildren: diff => diff.children, }) - return promiseAllRejectLate(unpacks) - .then(() => process.emit('timeEnd', 'reify:unpack')) + return promiseAllRejectLate(unpacks).then(timeEnd) } // This is the part where we move back the unchanging nodes that were @@ -1054,7 +1049,7 @@ module.exports = cls => class Reifier extends cls { // This is sort of an inverse diff tree, of all the nodes where // the actualTree and idealTree _don't_ differ, starting from the // shallowest nodes that we moved aside in the first place. - process.emit('time', 'reify:unretire') + const timeEnd = time.start('reify:unretire') const moves = this[_retiredPaths] this[_retiredUnchanged] = {} return promiseAllRejectLate(this.diff.children.map(diff => { @@ -1102,8 +1097,7 @@ module.exports = cls => class Reifier extends cls { const dir = bd && bd.length ? node.path + '/node_modules' : node.path return mkdir(dir, { recursive: true }).then(() => this[_moveContents](node, fromPath)) })) - })) - .then(() => process.emit('timeEnd', 'reify:unretire')) + })).then(timeEnd) } // move the contents from the fromPath to the node.path @@ -1135,7 +1129,7 @@ module.exports = cls => class Reifier extends cls { } [_build] () { - process.emit('time', 'reify:build') + const timeEnd = time.start('reify:build') // for all the things being installed, run their appropriate scripts // run in tip->root order, so as to be more likely to build a node's @@ -1167,8 +1161,7 @@ module.exports = cls => class Reifier extends cls { } } - return this.rebuild({ nodes, handleOptionalFailure: true }) - .then(() => process.emit('timeEnd', 'reify:build')) + return this.rebuild({ nodes, handleOptionalFailure: true }).then(timeEnd) } // the tree is pretty much built now, so it's cleanup time. @@ -1176,7 +1169,7 @@ module.exports = cls => class Reifier extends cls { // If this fails, there isn't much we can do but tell the user about it. // Thankfully, it's pretty unlikely that it'll fail, since rm is a node builtin. async [_removeTrash] () { - process.emit('time', 'reify:trash') + const timeEnd = time.start('reify:trash') const promises = [] const failures = [] const _rm = path => rm(path, { recursive: true, force: true }).catch(er => failures.push([path, er])) @@ -1189,7 +1182,8 @@ module.exports = cls => class Reifier extends cls { if (failures.length) { log.warn('cleanup', 'Failed to remove some directories', failures) } - process.emit('timeEnd', 'reify:trash') + + timeEnd() } // last but not least, we save the ideal tree metadata to the package-lock @@ -1222,7 +1216,7 @@ module.exports = cls => class Reifier extends cls { return false } - process.emit('time', 'reify:save') + const timeEnd = time.start('reify:save') const updatedTrees = new Set() const updateNodes = nodes => { @@ -1460,7 +1454,7 @@ module.exports = cls => class Reifier extends cls { }) } - process.emit('timeEnd', 'reify:save') + timeEnd() return true } @@ -1571,17 +1565,14 @@ module.exports = cls => class Reifier extends cls { const { scripts = {} } = pkg for (const event of ['predependencies', 'dependencies', 'postdependencies']) { if (Object.prototype.hasOwnProperty.call(scripts, event)) { - const timer = `reify:run:${event}` - process.emit('time', timer) log.info('run', pkg._id, event, scripts[event]) - await runScript({ + await time.start(`reify:run:${event}`, () => runScript({ event, path, pkg, stdio, scriptShell: this.options.scriptShell, - }) - process.emit('timeEnd', timer) + })) } } } diff --git a/workspaces/arborist/lib/audit-report.js b/workspaces/arborist/lib/audit-report.js index 7e5ac2071dcbe..f7700ce9119de 100644 --- a/workspaces/arborist/lib/audit-report.js +++ b/workspaces/arborist/lib/audit-report.js @@ -13,7 +13,7 @@ const _fixAvailable = Symbol('fixAvailable') const _checkTopNode = Symbol('checkTopNode') const _init = Symbol('init') const _omit = Symbol('omit') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const fetch = require('npm-registry-fetch') @@ -117,7 +117,7 @@ class AuditReport extends Map { } async [_init] () { - process.emit('time', 'auditReport:init') + const timeEnd = time.start('auditReport:init') const promises = [] for (const [name, advisories] of Object.entries(this.report)) { @@ -210,7 +210,8 @@ class AuditReport extends Map { } } } - process.emit('timeEnd', 'auditReport:init') + + timeEnd() } [_checkTopNode] (topNode, vuln, spec) { @@ -306,7 +307,7 @@ class AuditReport extends Map { return null } - process.emit('time', 'auditReport:getReport') + const timeEnd = time.start('auditReport:getReport') try { try { // first try the super fast bulk advisory listing @@ -347,7 +348,7 @@ class AuditReport extends Map { this.error = er return null } finally { - process.emit('timeEnd', 'auditReport:getReport') + timeEnd() } } } diff --git a/workspaces/arborist/test/arborist/reify.js b/workspaces/arborist/test/arborist/reify.js index db7df07e46bcd..d0615add3540a 100644 --- a/workspaces/arborist/test/arborist/reify.js +++ b/workspaces/arborist/test/arborist/reify.js @@ -246,17 +246,17 @@ t.test('omit peer deps', t => { // in this one we also snapshot the timers, mostly just as a smoke test const timers = {} const finishedTimers = [] - const onTime = name => { - t.notOk(timers[name], 'should not have duplicated timers started') - timers[name] = true - } - const onTimeEnd = name => { - t.ok(timers[name], 'should not end unstarted timer') - delete timers[name] - finishedTimers.push(name) + const onTime = (level, name) => { + if (level === 'start') { + t.notOk(timers[name], 'should not have duplicated timers started') + timers[name] = true + } else if (level === 'end') { + t.ok(timers[name], 'should not end unstarted timer') + delete timers[name] + finishedTimers.push(name) + } } process.on('time', onTime) - process.on('timeEnd', onTimeEnd) return reify(path, { omit: ['peer'] }) .then(tree => { @@ -277,7 +277,6 @@ t.test('omit peer deps', t => { // eslint-disable-next-line promise/always-return .then(() => { process.removeListener('time', onTime) - process.removeListener('timeEnd', onTimeEnd) finishedTimers.sort(localeCompare) t.matchSnapshot(finishedTimers, 'finished timers') t.strictSame(timers, {}, 'should have no timers in progress now') diff --git a/workspaces/config/lib/index.js b/workspaces/config/lib/index.js index 0d7ba3eb21f4e..c3e73dc761c57 100644 --- a/workspaces/config/lib/index.js +++ b/workspaces/config/lib/index.js @@ -2,7 +2,7 @@ const { walkUp } = require('walk-up-path') const ini = require('ini') const nopt = require('nopt') -const { log } = require('proc-log') +const { log, time } = require('proc-log') const { resolve, dirname, join } = require('node:path') const { homedir } = require('node:os') @@ -201,7 +201,7 @@ class Config { } // create the object for flat options passed to deps - process.emit('time', 'config:load:flatten') + const timeEnd = time.start('config:load:flatten') this.#flatOptions = {} // walk from least priority to highest for (const { data } of this.data.values()) { @@ -209,7 +209,7 @@ class Config { } this.#flatOptions.nodeBin = this.execPath this.#flatOptions.npmBin = this.npmBin - process.emit('timeEnd', 'config:load:flatten') + timeEnd() return this.#flatOptions } @@ -233,37 +233,27 @@ class Config { throw new Error('attempting to load npm config multiple times') } - process.emit('time', 'config:load') + const timeEnd = time.start('config:load') + // first load the defaults, which sets the global prefix - process.emit('time', 'config:load:defaults') - this.loadDefaults() - process.emit('timeEnd', 'config:load:defaults') + time.start('config:load:defaults', () => this.loadDefaults()) // next load the builtin config, as this sets new effective defaults - process.emit('time', 'config:load:builtin') - await this.loadBuiltinConfig() - process.emit('timeEnd', 'config:load:builtin') + await time.start('config:load:builtin', () => this.loadBuiltinConfig()) // cli and env are not async, and can set the prefix, relevant to project - process.emit('time', 'config:load:cli') - this.loadCLI() - process.emit('timeEnd', 'config:load:cli') - process.emit('time', 'config:load:env') - this.loadEnv() - process.emit('timeEnd', 'config:load:env') + time.start('config:load:cli', () => this.loadCLI()) + + time.start('config:load:env', () => this.loadEnv()) // next project config, which can affect userconfig location - process.emit('time', 'config:load:project') - await this.loadProjectConfig() - process.emit('timeEnd', 'config:load:project') + await time.start('config:load:project', () => this.loadProjectConfig()) + // then user config, which can affect globalconfig location - process.emit('time', 'config:load:user') - await this.loadUserConfig() - process.emit('timeEnd', 'config:load:user') + await time.start('config:load:user', () => this.loadUserConfig()) + // last but not least, global config file - process.emit('time', 'config:load:global') - await this.loadGlobalConfig() - process.emit('timeEnd', 'config:load:global') + await time.start('config:load:global', () => this.loadGlobalConfig()) // set this before calling setEnvs, so that we don't have to share // private attributes, as that module also does a bunch of get operations @@ -272,11 +262,9 @@ class Config { // set proper globalPrefix now that everything is loaded this.globalPrefix = this.get('prefix') - process.emit('time', 'config:load:setEnvs') - this.setEnvs() - process.emit('timeEnd', 'config:load:setEnvs') + time.start('config:load:setEnvs', () => this.setEnvs()) - process.emit('timeEnd', 'config:load') + timeEnd() } loadDefaults () { @@ -601,9 +589,8 @@ class Config { } async #loadFile (file, type) { - process.emit('time', 'config:load:file:' + file) // only catch the error from readFile, not from the loadObject call - await readFile(file, 'utf8').then( + await time.start(`config:load:file:${file}`, () => readFile(file, 'utf8').then( data => { const parsedConfig = ini.parse(data) if (type === 'project' && parsedConfig.prefix) { @@ -614,8 +601,7 @@ class Config { return this.#loadObject(parsedConfig, type, file) }, er => this.#loadObject(null, type, file, er) - ) - process.emit('timeEnd', 'config:load:file:' + file) + )) } loadBuiltinConfig () {